The originate-coa virtual server includes a switch condition using the Response-Packet-Type attribute in the post-proxy section. However this attribute is not populated for responses to coa or disconnect requests. The Packet-Type attribute is populated in the proxy-reply list (which is perhaps to be inferred from the comments in the originate-coa file). Is the lack of information in the Response-Packet-Type attribute expected in a response to a coa or disconnect request and the switch should be updated to use %{proxy-reply:Packet-Type} (this does work) or should the Response-Packet-Type attribute be populated for a response to a coa or disconnect request? This is using 2.1.10 up to git 288647f (to pull in the coa correlation fixes) Snippet: Tue Jun 29 15:27:09 2010 : Info: +- entering group post-proxy {...} Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-request:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{request:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{reply:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Packet-Type} -> Disconnect-NAK Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-request:Packet-Type} -> Disconnect-Request Tue Jun 29 15:27:09 2010 : Info: expand: %{request:Packet-Type} -> Accounting-Request Tue Jun 29 15:27:09 2010 : Info: expand: %{reply:Packet-Type} -> Accounting-Response Tue Jun 29 15:27:09 2010 : Info: expand: %{Packet-Type} -> Accounting-Request Full Debug: [root@radius-dev sites-enabled]# radiusd -Xx Tue Jun 29 15:26:26 2010 : Info: FreeRADIUS Version 2.1.10, for host x86_64-redhat-linux-gnu, built on Jun 14 2010 at 15:41:02 Tue Jun 29 15:26:26 2010 : Info: Copyright (C) 1999-2009 The FreeRADIUS server project and contributors. Tue Jun 29 15:26:26 2010 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Tue Jun 29 15:26:26 2010 : Info: PARTICULAR PURPOSE. Tue Jun 29 15:26:26 2010 : Info: You may redistribute copies of FreeRADIUS under the terms of the Tue Jun 29 15:26:26 2010 : Info: GNU General Public License v2. Tue Jun 29 15:26:26 2010 : Info: Starting - reading configuration files ... Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/radiusd.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/proxy.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/clients.conf Tue Jun 29 15:26:26 2010 : Debug: including files in directory /etc/raddb/modules/ Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/otp Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/detail.wimax Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/realm Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/checkval Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/detail.example.com Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/policy Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/wimax Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/smsotp Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/sql_log Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/passwd Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/preprocess Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/perl Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/attr_rewrite Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/detail.wisper Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/always Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/counter Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/linelog Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/ippool Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/digest Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/etc_group Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/ntlm_auth Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/exec Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/chap Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/files Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/pap Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/mac2ip Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/smbpasswd Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/sqlcounter_expire_on_login Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/inner-eap Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/mschap Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/unix Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/pam Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/mac2vlan Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/echo Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/expr Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/attr_filter Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/detail Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/expiration Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/cui Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/acct_unique Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/logintime Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/radutmp Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/detail.log Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/sradutmp Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/eap.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sql-wisper.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sql/mysql/dialup.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sql/mysql/dialup.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sql/mysql/wimax.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/policy.conf Tue Jun 29 15:26:26 2010 : Debug: including files in directory /etc/raddb/sites-enabled/ Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/buffered-sql-wisper Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/wimax-asn Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/default Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/eap-stress-test Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/status Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/originate-coa-wimax Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/control-socket Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/buffered-sql-wimax Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/inner-tunnel Tue Jun 29 15:26:26 2010 : Debug: main { Tue Jun 29 15:26:26 2010 : Debug: user = "radiusd" Tue Jun 29 15:26:26 2010 : Debug: group = "radiusd" Tue Jun 29 15:26:26 2010 : Debug: allow_core_dumps = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: including dictionary file /etc/raddb/dictionary Tue Jun 29 15:26:26 2010 : Debug: main { Tue Jun 29 15:26:26 2010 : Debug: prefix = "/usr" Tue Jun 29 15:26:26 2010 : Debug: localstatedir = "/var" Tue Jun 29 15:26:26 2010 : Debug: logdir = "/var/log/radius" Tue Jun 29 15:26:26 2010 : Debug: libdir = "/usr/lib64/freeradius" Tue Jun 29 15:26:26 2010 : Debug: radacctdir = "/var/log/radius/radacct" Tue Jun 29 15:26:26 2010 : Debug: hostname_lookups = no Tue Jun 29 15:26:26 2010 : Debug: max_request_time = 30 Tue Jun 29 15:26:26 2010 : Debug: cleanup_delay = 3 Tue Jun 29 15:26:26 2010 : Debug: max_requests = 25000 Tue Jun 29 15:26:26 2010 : Debug: pidfile = "/var/run/radiusd/radiusd.pid" Tue Jun 29 15:26:26 2010 : Debug: checkrad = "/usr/sbin/checkrad" Tue Jun 29 15:26:26 2010 : Debug: debug_level = 0 Tue Jun 29 15:26:26 2010 : Debug: proxy_requests = yes Tue Jun 29 15:26:26 2010 : Debug: log { Tue Jun 29 15:26:26 2010 : Debug: stripped_names = no Tue Jun 29 15:26:26 2010 : Debug: auth = yes Tue Jun 29 15:26:26 2010 : Debug: auth_badpass = no Tue Jun 29 15:26:26 2010 : Debug: auth_goodpass = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: security { Tue Jun 29 15:26:26 2010 : Debug: max_attributes = 200 Tue Jun 29 15:26:26 2010 : Debug: reject_delay = 1 Tue Jun 29 15:26:26 2010 : Debug: status_server = yes Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: radiusd: #### Loading Realms and Home Servers #### Tue Jun 29 15:26:26 2010 : Debug: proxy server { Tue Jun 29 15:26:26 2010 : Debug: retry_delay = 5 Tue Jun 29 15:26:26 2010 : Debug: retry_count = 3 Tue Jun 29 15:26:26 2010 : Debug: default_fallback = no Tue Jun 29 15:26:26 2010 : Debug: dead_time = 120 Tue Jun 29 15:26:26 2010 : Debug: wake_all_if_all_dead = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: home_server localhost { Tue Jun 29 15:26:26 2010 : Debug: ipaddr = 127.0.0.1 Tue Jun 29 15:26:26 2010 : Debug: port = 1812 Tue Jun 29 15:26:26 2010 : Debug: type = "auth" Tue Jun 29 15:26:26 2010 : Debug: secret = "secret" Tue Jun 29 15:26:26 2010 : Debug: response_window = 20 Tue Jun 29 15:26:26 2010 : Debug: max_outstanding = 65536 Tue Jun 29 15:26:26 2010 : Debug: require_message_authenticator = no Tue Jun 29 15:26:26 2010 : Debug: zombie_period = 40 Tue Jun 29 15:26:26 2010 : Debug: status_check = "status-server" Tue Jun 29 15:26:26 2010 : Debug: ping_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: check_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: num_answers_to_alive = 3 Tue Jun 29 15:26:26 2010 : Debug: num_pings_to_alive = 3 Tue Jun 29 15:26:26 2010 : Debug: revive_interval = 120 Tue Jun 29 15:26:26 2010 : Debug: status_check_timeout = 4 Tue Jun 29 15:26:26 2010 : Debug: irt = 2 Tue Jun 29 15:26:26 2010 : Debug: mrt = 16 Tue Jun 29 15:26:26 2010 : Debug: mrc = 5 Tue Jun 29 15:26:26 2010 : Debug: mrd = 30 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: home_server_pool my_auth_failover { Tue Jun 29 15:26:26 2010 : Debug: type = fail-over Tue Jun 29 15:26:26 2010 : Debug: home_server = localhost Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: realm example.com { Tue Jun 29 15:26:26 2010 : Debug: auth_pool = my_auth_failover Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: realm LOCAL { Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: home_server wichorus-coa { Tue Jun 29 15:26:26 2010 : Debug: ipaddr = 172.17.2.20 Tue Jun 29 15:26:26 2010 : Debug: port = 3799 Tue Jun 29 15:26:26 2010 : Debug: type = "coa" Tue Jun 29 15:26:26 2010 : Debug: secret = "secret" Tue Jun 29 15:26:26 2010 : Debug: response_window = 30 Tue Jun 29 15:26:26 2010 : Debug: max_outstanding = 65536 Tue Jun 29 15:26:26 2010 : Debug: zombie_period = 40 Tue Jun 29 15:26:26 2010 : Debug: status_check = "none" Tue Jun 29 15:26:26 2010 : Debug: ping_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: check_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: num_answers_to_alive = 3 Tue Jun 29 15:26:26 2010 : Debug: num_pings_to_alive = 3 Tue Jun 29 15:26:26 2010 : Debug: revive_interval = 300 Tue Jun 29 15:26:26 2010 : Debug: status_check_timeout = 4 Tue Jun 29 15:26:26 2010 : Debug: irt = 2 Tue Jun 29 15:26:26 2010 : Debug: mrt = 16 Tue Jun 29 15:26:26 2010 : Debug: mrc = 5 Tue Jun 29 15:26:26 2010 : Debug: mrd = 30 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: home_server_pool coa { Tue Jun 29 15:26:26 2010 : Debug: type = fail-over Tue Jun 29 15:26:26 2010 : Debug: virtual_server = originate-coa-wimax Tue Jun 29 15:26:26 2010 : Debug: home_server = wichorus-coa Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: radiusd: #### Loading Clients #### Tue Jun 29 15:26:26 2010 : Debug: client 172.17.2.20 { Tue Jun 29 15:26:26 2010 : Debug: require_message_authenticator = no Tue Jun 29 15:26:26 2010 : Debug: secret = "secret" Tue Jun 29 15:26:26 2010 : Debug: shortname = "wichorus-asn" Tue Jun 29 15:26:26 2010 : Debug: nastype = "other" Tue Jun 29 15:26:26 2010 : Debug: virtual_server = "wimax-asn" Tue Jun 29 15:26:26 2010 : Debug: coa_server = "coa" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: radiusd: #### Instantiating modules #### Tue Jun 29 15:26:26 2010 : Debug: instantiate { Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_exec, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_exec Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating exec Tue Jun 29 15:26:26 2010 : Debug: exec { Tue Jun 29 15:26:26 2010 : Debug: wait = no Tue Jun 29 15:26:26 2010 : Debug: input_pairs = "request" Tue Jun 29 15:26:26 2010 : Debug: shell_escape = yes Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_expr, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_expr Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating expr Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_expiration, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_expiration Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating expiration Tue Jun 29 15:26:26 2010 : Debug: expiration { Tue Jun 29 15:26:26 2010 : Debug: reply-message = "Password Has Expired " Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_logintime, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_logintime Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating logintime Tue Jun 29 15:26:26 2010 : Debug: logintime { Tue Jun 29 15:26:26 2010 : Debug: reply-message = "You are calling outside your allowed timespan " Tue Jun 29 15:26:26 2010 : Debug: minimum-timeout = 60 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: radiusd: #### Loading Virtual Servers #### Tue Jun 29 15:26:26 2010 : Debug: server buffered-sql-wisper { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking preacct {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_preprocess, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_preprocess Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating preprocess Tue Jun 29 15:26:26 2010 : Debug: preprocess { Tue Jun 29 15:26:26 2010 : Debug: huntgroups = "/etc/raddb/huntgroups" Tue Jun 29 15:26:26 2010 : Debug: hints = "/etc/raddb/hints" Tue Jun 29 15:26:26 2010 : Debug: with_ascend_hack = no Tue Jun 29 15:26:26 2010 : Debug: ascend_channels_per_line = 23 Tue Jun 29 15:26:26 2010 : Debug: with_ntdomain_hack = no Tue Jun 29 15:26:26 2010 : Debug: with_specialix_jetstream_hack = no Tue Jun 29 15:26:26 2010 : Debug: with_cisco_vsa_hack = no Tue Jun 29 15:26:26 2010 : Debug: with_alvarion_vsa_hack = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_acct_unique, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_acct_unique Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating acct_unique Tue Jun 29 15:26:26 2010 : Debug: acct_unique { Tue Jun 29 15:26:26 2010 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking accounting {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_sql, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_sql Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating sqlmain Tue Jun 29 15:26:26 2010 : Debug: sql sqlmain { Tue Jun 29 15:26:26 2010 : Debug: driver = "rlm_sql_mysql" Tue Jun 29 15:26:26 2010 : Debug: server = "172.17.0.150" Tue Jun 29 15:26:26 2010 : Debug: port = "" Tue Jun 29 15:26:26 2010 : Debug: login = "radius" Tue Jun 29 15:26:26 2010 : Debug: password = "blah" Tue Jun 29 15:26:26 2010 : Debug: radius_db = "radius2" Tue Jun 29 15:26:26 2010 : Debug: read_groups = yes Tue Jun 29 15:26:26 2010 : Debug: sqltrace = no Tue Jun 29 15:26:26 2010 : Debug: sqltracefile = "/var/log/radius/sqltrace.sql" Tue Jun 29 15:26:26 2010 : Debug: readclients = yes Tue Jun 29 15:26:26 2010 : Debug: deletestalesessions = yes Tue Jun 29 15:26:26 2010 : Debug: num_sql_socks = 15 Tue Jun 29 15:26:26 2010 : Debug: lifetime = 0 Tue Jun 29 15:26:26 2010 : Debug: max_queries = 0 Tue Jun 29 15:26:26 2010 : Debug: sql_user_name = "%{User-Name}" Tue Jun 29 15:26:26 2010 : Debug: default_user_profile = "" Tue Jun 29 15:26:26 2010 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" Tue Jun 29 15:26:26 2010 : Debug: authorize_check_query = "SELECT id, username, attribute, value, op FROM radcheck WHERE username = BINARY '%{SQL-User-Name}' ORDER BY id" Tue Jun 29 15:26:26 2010 : Debug: authorize_reply_query = "SELECT id, username, attribute, value, op FROM radreply WHERE username = BINARY '%{SQL-User-Name}' ORDER BY id" Tue Jun 29 15:26:26 2010 : Debug: authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id" Tue Jun 29 15:26:26 2010 : Debug: authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id" Tue Jun 29 15:26:26 2010 : 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 acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= '%S'" Tue Jun 29 15:26:26 2010 : 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 Jun 29 15:26:26 2010 : 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 Jun 29 15:26:26 2010 : 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 Jun 29 15:26:26 2010 : 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 Jun 29 15:26:26 2010 : 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 Jun 29 15:26:26 2010 : 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 Jun 29 15:26:26 2010 : Debug: group_membership_query = "SELECT groupname FROM radusergroup WHERE username = BINARY '%{SQL-User-Name}' ORDER BY priority" Tue Jun 29 15:26:26 2010 : Debug: connect_failure_retry_delay = 60 Tue Jun 29 15:26:26 2010 : Debug: simul_count_query = "" Tue Jun 29 15:26:26 2010 : Debug: simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" Tue Jun 29 15:26:26 2010 : Debug: postauth_query = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" Tue Jun 29 15:26:26 2010 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /{}" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect to radius@172.17.0.150:/radius2 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #0 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #1 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #2 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #3 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #4 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #5 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #6 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #7 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #8 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #9 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #10 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #11 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #12 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #13 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #14 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): Processing generate_sql_clients Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): Reserving sql socket id: 14 ...snip... Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): Released sql socket id: 14 Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server wimax-asn { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authenticate {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_eap, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_eap Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating eap Tue Jun 29 15:26:26 2010 : Debug: eap { Tue Jun 29 15:26:26 2010 : Debug: default_eap_type = "ttls" Tue Jun 29 15:26:26 2010 : Debug: timer_expire = 60 Tue Jun 29 15:26:26 2010 : Debug: ignore_unknown_eap_types = yes Tue Jun 29 15:26:26 2010 : Debug: cisco_accounting_username_bug = no Tue Jun 29 15:26:26 2010 : Debug: max_sessions = 2048 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to sub-module rlm_eap_tls Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating eap-tls Tue Jun 29 15:26:26 2010 : Debug: tls { Tue Jun 29 15:26:26 2010 : Debug: rsa_key_exchange = no Tue Jun 29 15:26:26 2010 : Debug: dh_key_exchange = yes Tue Jun 29 15:26:26 2010 : Debug: rsa_key_length = 512 Tue Jun 29 15:26:26 2010 : Debug: dh_key_length = 512 Tue Jun 29 15:26:26 2010 : Debug: verify_depth = 0 Tue Jun 29 15:26:26 2010 : Debug: pem_file_type = yes Tue Jun 29 15:26:26 2010 : Debug: private_key_file = "/etc/raddb/certs/radius-dev_key.pem" Tue Jun 29 15:26:26 2010 : Debug: certificate_file = "/etc/raddb/certs/radius-dev_chain.pem" Tue Jun 29 15:26:26 2010 : Debug: CA_file = "/etc/raddb/certs/ca.pem" Tue Jun 29 15:26:26 2010 : Debug: private_key_password = "blah" Tue Jun 29 15:26:26 2010 : Debug: dh_file = "/etc/raddb/certs/dh" Tue Jun 29 15:26:26 2010 : Debug: random_file = "/etc/raddb/certs/random" Tue Jun 29 15:26:26 2010 : Debug: fragment_size = 1024 Tue Jun 29 15:26:26 2010 : Debug: include_length = yes Tue Jun 29 15:26:26 2010 : Debug: check_crl = no Tue Jun 29 15:26:26 2010 : Debug: cipher_list = "DEFAULT" Tue Jun 29 15:26:26 2010 : Debug: cache { Tue Jun 29 15:26:26 2010 : Debug: enable = yes Tue Jun 29 15:26:26 2010 : Debug: lifetime = 24 Tue Jun 29 15:26:26 2010 : Debug: max_entries = 0 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to sub-module rlm_eap_ttls Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating eap-ttls Tue Jun 29 15:26:26 2010 : Debug: ttls { Tue Jun 29 15:26:26 2010 : Debug: default_eap_type = "mschapv2" Tue Jun 29 15:26:26 2010 : Debug: copy_request_to_tunnel = no Tue Jun 29 15:26:26 2010 : Debug: use_tunneled_reply = yes Tue Jun 29 15:26:26 2010 : Debug: virtual_server = "inner-tunnel" Tue Jun 29 15:26:26 2010 : Debug: include_length = yes Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to sub-module rlm_eap_mschapv2 Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating eap-mschapv2 Tue Jun 29 15:26:26 2010 : Debug: mschapv2 { Tue Jun 29 15:26:26 2010 : Debug: with_ntdomain_hack = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Loading virtual module init_wimax Tue Jun 29 15:26:26 2010 : Debug: Module: Loading virtual module verify_wimax_asn Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_always, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_always Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating reject Tue Jun 29 15:26:26 2010 : Debug: always reject { Tue Jun 29 15:26:26 2010 : Debug: rcode = "reject" Tue Jun 29 15:26:26 2010 : Debug: simulcount = 0 Tue Jun 29 15:26:26 2010 : Debug: mpp = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating noop Tue Jun 29 15:26:26 2010 : Debug: always noop { Tue Jun 29 15:26:26 2010 : Debug: rcode = "noop" Tue Jun 29 15:26:26 2010 : Debug: simulcount = 0 Tue Jun 29 15:26:26 2010 : Debug: mpp = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_wimax, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_wimax Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating wimax Tue Jun 29 15:26:26 2010 : Debug: wimax { Tue Jun 29 15:26:26 2010 : Debug: delete_mppe_keys = yes Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_realm, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_realm Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating suffix Tue Jun 29 15:26:26 2010 : Debug: realm suffix { Tue Jun 29 15:26:26 2010 : Debug: format = "suffix" Tue Jun 29 15:26:26 2010 : Debug: delimiter = "@" Tue Jun 29 15:26:26 2010 : Debug: ignore_default = no Tue Jun 29 15:26:26 2010 : Debug: ignore_null = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking preacct {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking accounting {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_detail, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_detail Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating detail_wimax Tue Jun 29 15:26:26 2010 : Debug: detail detail_wimax { Tue Jun 29 15:26:26 2010 : Debug: detailfile = "/var/log/radius/radacct/wimax/detail-%Y%m%d" Tue Jun 29 15:26:26 2010 : Debug: header = "%t" Tue Jun 29 15:26:26 2010 : Debug: detailperm = 432 Tue Jun 29 15:26:26 2010 : Debug: dirperm = 493 Tue Jun 29 15:26:26 2010 : Debug: locking = no Tue Jun 29 15:26:26 2010 : Debug: log_packet_header = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating sqlsession Tue Jun 29 15:26:26 2010 : Debug: sql sqlsession { Tue Jun 29 15:26:26 2010 : Debug: driver = "rlm_sql_mysql" Tue Jun 29 15:26:26 2010 : Debug: server = "172.17.0.150" Tue Jun 29 15:26:26 2010 : Debug: port = "" Tue Jun 29 15:26:26 2010 : Debug: login = "radius" Tue Jun 29 15:26:26 2010 : Debug: password = "blah" Tue Jun 29 15:26:26 2010 : Debug: radius_db = "radius2" Tue Jun 29 15:26:26 2010 : Debug: read_groups = no Tue Jun 29 15:26:26 2010 : Debug: sqltrace = no Tue Jun 29 15:26:26 2010 : Debug: sqltracefile = "/var/log/radius/sqltrace.sql" Tue Jun 29 15:26:26 2010 : Debug: readclients = no Tue Jun 29 15:26:26 2010 : Debug: deletestalesessions = no Tue Jun 29 15:26:26 2010 : Debug: num_sql_socks = 15 Tue Jun 29 15:26:26 2010 : Debug: lifetime = 0 Tue Jun 29 15:26:26 2010 : Debug: max_queries = 0 Tue Jun 29 15:26:26 2010 : Debug: sql_user_name = "%{User-Name}" Tue Jun 29 15:26:26 2010 : Debug: default_user_profile = "" Tue Jun 29 15:26:26 2010 : Debug: nas_query = "SELECT id,nasname,shortname,type,secret FROM nas" Tue Jun 29 15:26:26 2010 : Debug: authorize_check_query = "SELECT id, username, 'WiMAX-hHA-IP-MIP4' as attribute, `hha-ip-address` as value, '==' as op FROM wimax WHERE username = BINARY '%{SQL-User-Name}'" Tue Jun 29 15:26:26 2010 : Debug: authorize_reply_query = "select id, username, 'WiMAX-MN-hHA-MIP4-Key' as attribute, `mn-ha-key` as value, ':=' as op FROM wimax WHERE username = BINARY '%{SQL-User-Name}' AND `mn-ha-key-spi` = %{WiMAX-MN-hHA-MIP4-SPI}" Tue Jun 29 15:26:26 2010 : Debug: authorize_group_check_query = "" Tue Jun 29 15:26:26 2010 : Debug: authorize_group_reply_query = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_onoff_query = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_update_query = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_update_query_alt = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_start_query = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_start_query_alt = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_stop_query = " DELETE FROM wimax WHERE `username` = BINARY '%{SQL-User-Name}' AND `wimax-session-id` = '%{Acct-Multi-Session-Id}'" Tue Jun 29 15:26:26 2010 : Debug: accounting_stop_query_alt = "" Tue Jun 29 15:26:26 2010 : Debug: connect_failure_retry_delay = 60 Tue Jun 29 15:26:26 2010 : Debug: simul_count_query = "" Tue Jun 29 15:26:26 2010 : Debug: simul_verify_query = "" Tue Jun 29 15:26:26 2010 : Debug: postauth_query = "INSERT INTO wimax (`username`, `wimax-session-id`, `calling-station-id`, `nas-id`, `nas-ip-address`, `framed-ip-address`, `mip-rk`, `fa-rk`, `fa-rk-spi`, `mn-ha-key`, `mn-ha-spi`, `hha-ip-address`, `vha-ip-address`, `authdate`, `lifetime` ) VALUES ( '%{SQL-User-Name}', %{reply:WiMAX-AAA-Session-Id}, '%{Calling-Station-Id}', '%{NAS-Identifier}', '%{NAS-IP-Address}', '%{reply:Framed-IP-Address}', NULL, %{%{reply:WiMAX-FA-RK-Key}:-NULL}, %{%{reply:WiMAX-FA-RK-SPI}:-NULL}, %{%{reply:WiMAX-MN-hHA-MIP4-Key}:-%{%{reply:WiMAX-MN-hHA-MIP6-Key}:-NULL}}, %{%{reply:WiMAX-MN-hHA-MIP4-SPI}:-%{%{reply:WiMAX-MN-hHA-MIP6-SPI}:-NULL}}, '%{%{reply:WiMAX-hHA-IP-MIP4}:-%{reply:WiMAX-hHA-IP-MIP6}}', '%{%{reply:WiMAX-vHA-IP-MIP4}:-%{reply:WiMAX-vHA-IP-MIP6}}', '%S', '%{%{reply:Session-Timeout}:-86400}' )" Tue Jun 29 15:26:26 2010 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect to radius@172.17.0.150:/radius2 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #0 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #1 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #2 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #3 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #4 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #5 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #6 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #7 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #8 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #9 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #10 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #11 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #12 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #13 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #14 Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_attr_filter, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_attr_filter Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating attr_filter.accounting_response Tue Jun 29 15:26:26 2010 : Debug: attr_filter attr_filter.accounting_response { Tue Jun 29 15:26:26 2010 : Debug: attrsfile = "/etc/raddb/attrs.accounting_response" Tue Jun 29 15:26:26 2010 : Debug: key = "%{User-Name}" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking session {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-auth {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Loading virtual module negotiate_ip_technology Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating handled Tue Jun 29 15:26:26 2010 : Debug: always handled { Tue Jun 29 15:26:26 2010 : Debug: rcode = "handled" Tue Jun 29 15:26:26 2010 : Debug: simulcount = 0 Tue Jun 29 15:26:26 2010 : Debug: mpp = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating attr_filter.access_reject Tue Jun 29 15:26:26 2010 : Debug: attr_filter attr_filter.access_reject { Tue Jun 29 15:26:26 2010 : Debug: attrsfile = "/etc/raddb/attrs.access_reject" Tue Jun 29 15:26:26 2010 : Debug: key = "%{User-Name}" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server stress { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authenticate {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-auth {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server status { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating ok Tue Jun 29 15:26:26 2010 : Debug: always ok { Tue Jun 29 15:26:26 2010 : Debug: rcode = "ok" Tue Jun 29 15:26:26 2010 : Debug: simulcount = 0 Tue Jun 29 15:26:26 2010 : Debug: mpp = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server originate-coa-wimax { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating fail Tue Jun 29 15:26:26 2010 : Debug: always fail { Tue Jun 29 15:26:26 2010 : Debug: rcode = "fail" Tue Jun 29 15:26:26 2010 : Debug: simulcount = 0 Tue Jun 29 15:26:26 2010 : Debug: mpp = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server buffered-sql-wimax { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking preacct {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking accounting {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server inner-tunnel { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authenticate {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_pap, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_pap Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating pap Tue Jun 29 15:26:26 2010 : Debug: pap { Tue Jun 29 15:26:26 2010 : Debug: encryption_scheme = "auto" Tue Jun 29 15:26:26 2010 : Debug: auto_header = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_chap, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_chap Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating chap Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_mschap, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_mschap Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating mschap Tue Jun 29 15:26:26 2010 : Debug: mschap { Tue Jun 29 15:26:26 2010 : Debug: use_mppe = yes Tue Jun 29 15:26:26 2010 : Debug: require_encryption = no Tue Jun 29 15:26:26 2010 : Debug: require_strong = no Tue Jun 29 15:26:26 2010 : Debug: with_ntdomain_hack = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking session {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-auth {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authenticate {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking preacct {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking accounting {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating detail_wisper Tue Jun 29 15:26:26 2010 : Debug: detail detail_wisper { Tue Jun 29 15:26:26 2010 : Debug: detailfile = "/var/log/radius/radacct/wisper/detail-%Y%m%d" Tue Jun 29 15:26:26 2010 : Debug: header = "%t" Tue Jun 29 15:26:26 2010 : Debug: detailperm = 432 Tue Jun 29 15:26:26 2010 : Debug: dirperm = 493 Tue Jun 29 15:26:26 2010 : Debug: locking = no Tue Jun 29 15:26:26 2010 : Debug: log_packet_header = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-auth {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: radiusd: #### Opening IP addresses and Ports #### Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "auth" Tue Jun 29 15:26:26 2010 : Debug: ipaddr = * Tue Jun 29 15:26:26 2010 : Debug: port = 0 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "acct" Tue Jun 29 15:26:26 2010 : Debug: ipaddr = * Tue Jun 29 15:26:26 2010 : Debug: port = 0 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "control" Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: socket = "/var/run/radiusd/radiusd.sock" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "detail" Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: filename = "/var/log/radius/radacct/wisper/detail-*" Tue Jun 29 15:26:26 2010 : Debug: load_factor = 10 Tue Jun 29 15:26:26 2010 : Debug: poll_interval = 10 Tue Jun 29 15:26:26 2010 : Debug: retry_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "status" Tue Jun 29 15:26:26 2010 : Debug: ipaddr = * Tue Jun 29 15:26:26 2010 : Debug: port = 18120 Tue Jun 29 15:26:26 2010 : Debug: client admin { Tue Jun 29 15:26:26 2010 : Debug: ipaddr = 127.0.0.1 Tue Jun 29 15:26:26 2010 : Debug: require_message_authenticator = no Tue Jun 29 15:26:26 2010 : Debug: secret = "blah" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: client cacti { Tue Jun 29 15:26:26 2010 : Debug: ipaddr = 172.17.0.138 Tue Jun 29 15:26:26 2010 : Debug: require_message_authenticator = no Tue Jun 29 15:26:26 2010 : Debug: secret = "blah" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "detail" Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: filename = "/var/log/radius/radacct/wimax/detail-*" Tue Jun 29 15:26:26 2010 : Debug: load_factor = 10 Tue Jun 29 15:26:26 2010 : Debug: poll_interval = 20 Tue Jun 29 15:26:26 2010 : Debug: retry_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Listening on authentication address * port 1812 Tue Jun 29 15:26:26 2010 : Debug: Listening on accounting address * port 1813 Tue Jun 29 15:26:26 2010 : Debug: Listening on command file /var/run/radiusd/radiusd.sock Tue Jun 29 15:26:26 2010 : Debug: Listening on detail file /var/log/radius/radacct/wisper/detail-* as server buffered-sql-wisper Tue Jun 29 15:26:26 2010 : Debug: Detail listener /var/log/radius/radacct/wisper/detail-* state unopened signalled 0 waiting 10.000000 sec Tue Jun 29 15:26:26 2010 : Debug: Listening on status address * port 18120 as server status Tue Jun 29 15:26:26 2010 : Debug: Listening on detail file /var/log/radius/radacct/wimax/detail-* as server buffered-sql-wimax Tue Jun 29 15:26:26 2010 : Debug: Detail listener /var/log/radius/radacct/wimax/detail-* state unopened signalled 0 waiting 20.000000 sec Tue Jun 29 15:26:26 2010 : Debug: Listening on proxy address * port 1814 Tue Jun 29 15:26:26 2010 : Debug: Waking up in 9.9 seconds. Tue Jun 29 15:26:36 2010 : Debug: Polling for detail file /var/log/radius/radacct/wisper/detail-* Tue Jun 29 15:26:36 2010 : Debug: Detail listener /var/log/radius/radacct/wisper/detail-* state unopened signalled 0 waiting 10.176255 sec Tue Jun 29 15:26:36 2010 : Debug: Waking up in 9.9 seconds. Tue Jun 29 15:26:46 2010 : Debug: Polling for detail file /var/log/radius/radacct/wimax/detail-* Tue Jun 29 15:26:46 2010 : Debug: Detail listener /var/log/radius/radacct/wimax/detail-* state unopened signalled 0 waiting 19.786953 sec Tue Jun 29 15:26:46 2010 : Debug: Waking up in 0.1 seconds. Tue Jun 29 15:26:46 2010 : Debug: Polling for detail file /var/log/radius/radacct/wisper/detail-* Tue Jun 29 15:26:46 2010 : Debug: Detail listener /var/log/radius/radacct/wisper/detail-* state unopened signalled 0 waiting 9.933326 sec Tue Jun 29 15:26:46 2010 : Debug: Waking up in 9.9 seconds. Tue Jun 29 15:26:56 2010 : Debug: Polling for detail file /var/log/radius/radacct/wisper/detail-* Tue Jun 29 15:26:56 2010 : Debug: Detail listener /var/log/radius/radacct/wisper/detail-* state unopened signalled 0 waiting 9.832270 sec Tue Jun 29 15:26:56 2010 : Debug: Waking up in 9.6 seconds. Tue Jun 29 15:27:06 2010 : Debug: Polling for detail file /var/log/radius/radacct/wimax/detail-* Tue Jun 29 15:27:06 2010 : Debug: Detail listener /var/log/radius/radacct/wimax/detail-* state unopened signalled 0 waiting 20.068690 sec Tue Jun 29 15:27:06 2010 : Debug: Waking up in 0.1 seconds. Tue Jun 29 15:27:06 2010 : Debug: Polling for detail file /var/log/radius/radacct/wisper/detail-* Tue Jun 29 15:27:06 2010 : Debug: Detail listener /var/log/radius/radacct/wisper/detail-* state unopened signalled 0 waiting 9.778881 sec Tue Jun 29 15:27:06 2010 : Debug: Waking up in 9.7 seconds. rad_recv: Accounting-Request packet from host 172.17.2.20 port 6154, id=18, length=293 Acct-Status-Type = Interim-Update User-Name = "90E6A2CE0489B3FC32EBF73572CC92E6@test.wisper-wireless.com" NAS-IP-Address = 172.17.2.20 NAS-Port-Type = Wireless-802.16 NAS-Port = 5 NAS-Identifier = "melrose.asn-gw.wisper-wireless.com" WiMAX-NAP-Id = 0x575753 WiMAX-GMT-Timezone-offset = -18000 Calling-Station-Id = "\000&\202O\342\326" WiMAX-BS-Id = 0x000039fefe01 Event-Timestamp = "Aug 19 2009 22:33:29 CDT" Acct-Session-Id = "1A" Acct-Multi-Session-Id = "97be68067743d815f4ddd6d2c18b353a" Framed-IP-Address = 209.237.120.249 WiMAX-hHA-IP-MIP4 = 0.0.0.0 Acct-Session-Time = 240 WiMAX-Active-Time-Duration = 240 Acct-Input-Octets = 0 Acct-Output-Octets = 0 Acct-Input-Packets = 0 Acct-Output-Packets = 0 Tue Jun 29 15:27:09 2010 : Info: server wimax-asn { Tue Jun 29 15:27:09 2010 : Info: +- entering group preacct {...} Tue Jun 29 15:27:09 2010 : Info: ++[preprocess] returns ok Tue Jun 29 15:27:09 2010 : Info: [acct_unique] Hashing 'NAS-Port = 5,Client-IP-Address = 172.17.2.20,NAS-IP-Address = 172.17.2.20,Acct-Session-Id = "1A",User-Name = "90E6A2CE0489B3FC32EBF73572CC92E6@test.wisper-wireless.com"' Tue Jun 29 15:27:09 2010 : Info: [acct_unique] Acct-Unique-Session-ID = "deb71f7ac9251cc9". Tue Jun 29 15:27:09 2010 : Info: ++[acct_unique] returns ok Tue Jun 29 15:27:09 2010 : Debug: rlm_wimax: Fixing WiMAX binary Calling-Station-Id to 00-26-82-4f-e2-d6 Tue Jun 29 15:27:09 2010 : Info: ++[wimax] returns ok Tue Jun 29 15:27:09 2010 : Info: +- entering group accounting {...} Tue Jun 29 15:27:09 2010 : Info: [detail_wimax] expand: /var/log/radius/radacct/wimax/detail-%Y%m%d -> /var/log/radius/radacct/wimax/detail-20100629 Tue Jun 29 15:27:09 2010 : Info: [detail_wimax] /var/log/radius/radacct/wimax/detail-%Y%m%d expands to /var/log/radius/radacct/wimax/detail-20100629 Tue Jun 29 15:27:09 2010 : Info: [detail_wimax] expand: %t -> Tue Jun 29 15:27:09 2010 Tue Jun 29 15:27:09 2010 : Info: ++[detail_wimax] returns ok Tue Jun 29 15:27:09 2010 : Info: ++? if (Acct-Status-Type == Interim-Update) Tue Jun 29 15:27:09 2010 : Info: ? Evaluating (Acct-Status-Type == Interim-Update) -> TRUE Tue Jun 29 15:27:09 2010 : Info: ++? if (Acct-Status-Type == Interim-Update) -> TRUE Tue Jun 29 15:27:09 2010 : Info: ++- entering if (Acct-Status-Type == Interim-Update) {...} Tue Jun 29 15:27:09 2010 : Info: expand: %{User-Name} -> 90E6A2CE0489B3FC32EBF73572CC92E6@test.wisper-wireless.com Tue Jun 29 15:27:09 2010 : Info: expand: %{Calling-Station-Id} -> 00-26-82-4f-e2-d6 Tue Jun 29 15:27:09 2010 : Info: +++[disconnect] returns ok Tue Jun 29 15:27:09 2010 : Info: ++- if (Acct-Status-Type == Interim-Update) returns ok Tue Jun 29 15:27:09 2010 : Info: ++? if ((Acct-Status-Type == Stop) && (WiMAX-Session-Continue == False)) Tue Jun 29 15:27:09 2010 : Info: ?? Evaluating (Acct-Status-Type == Stop) -> FALSE Tue Jun 29 15:27:09 2010 : Info: ?? Skipping (WiMAX-Session-Continue == False) Tue Jun 29 15:27:09 2010 : Info: ++? if ((Acct-Status-Type == Stop) && (WiMAX-Session-Continue == False)) -> FALSE Tue Jun 29 15:27:09 2010 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> 90E6A2CE0489B3FC32EBF73572CC92E6@test.wisper-wireless.com Tue Jun 29 15:27:09 2010 : Debug: attr_filter: Matched entry DEFAULT at line 12 Tue Jun 29 15:27:09 2010 : Info: ++[attr_filter.accounting_response] returns updated Tue Jun 29 15:27:09 2010 : Info: } # server wimax-asn Sending Accounting-Response of id 18 to 172.17.2.20 port 6154 Tue Jun 29 15:27:09 2010 : Info: server originate-coa-wimax { Tue Jun 29 15:27:09 2010 : Info: WARNING: Empty pre-proxy section. Using default return values. Tue Jun 29 15:27:09 2010 : Info: } Sending Disconnect-Request of id 203 to 172.17.2.20 port 3799 User-Name = "90E6A2CE0489B3FC32EBF73572CC92E6@test.wisper-wireless.com" Calling-Station-Id = "00-26-82-4f-e2-d6" WiMAX-AAA-Session-Id = 0x626c6168626c6168626c6168 WiMAX-DM-Action-Code = Deregister-MS Tue Jun 29 15:27:09 2010 : Info: Finished request 0. Tue Jun 29 15:27:09 2010 : Info: Cleaning up request 0 ID 18 with timestamp +43 Tue Jun 29 15:27:09 2010 : Debug: Going to the next request Tue Jun 29 15:27:09 2010 : Debug: Waking up in 2.2 seconds. rad_recv: Disconnect-NAK packet from host 172.17.2.20 port 3799, id=203, length=32 Event-Timestamp = "Aug 19 2009 22:33:29 CDT" Error-Cause = Session-Context-Not-Found Tue Jun 29 15:27:09 2010 : Info: server originate-coa-wimax { Tue Jun 29 15:27:09 2010 : Info: +- entering group post-proxy {...} Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-request:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{request:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{reply:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Packet-Type} -> Disconnect-NAK Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-request:Packet-Type} -> Disconnect-Request Tue Jun 29 15:27:09 2010 : Info: expand: %{request:Packet-Type} -> Accounting-Request Tue Jun 29 15:27:09 2010 : Info: expand: %{reply:Packet-Type} -> Accounting-Response Tue Jun 29 15:27:09 2010 : Info: expand: %{Packet-Type} -> Accounting-Request Tue Jun 29 15:27:09 2010 : Info: ++[request] returns noop Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Packet-Type} -> Disconnect-NAK Tue Jun 29 15:27:09 2010 : Info: ++- entering switch %{proxy-reply:Packet-Type} {...} Tue Jun 29 15:27:09 2010 : Info: +++- entering case Disconnect-NAK {...} Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Error-Cause} -> Session-Context-Not-Found Tue Jun 29 15:27:09 2010 : Info: ++++[request] returns noop Tue Jun 29 15:27:09 2010 : Info: ++++[ok] returns ok Tue Jun 29 15:27:09 2010 : Info: +++- case Disconnect-NAK returns ok Tue Jun 29 15:27:09 2010 : Info: ++- switch %{proxy-reply:Packet-Type} returns ok Tue Jun 29 15:27:09 2010 : Info: } Tue Jun 29 15:27:09 2010 : Info: server wimax-asn { Tue Jun 29 15:27:09 2010 : Info: } # server wimax-asn Tue Jun 29 15:27:09 2010 : Info: Finished request 0. Tue Jun 29 15:27:09 2010 : Debug: Going to the next request Tue Jun 29 15:27:09 2010 : Debug: Waking up in 7.3 seconds. Ben