originate-coa virtual server

29 Jun 2010

      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

originate-coa virtual server

Ben Wiechman