Acct-Session-Id special characters changed to hex

26 May 2009

      Hi All,

I'm having some issues with the acct-session-id, where special characters 
for instance [] being converted to it's hex equivalent.

For example below, the Acct-Session-Id = "301[]426932183" when inserted 
into the accounting table it is inserted as 301=5B=5D426932183.

I have noticed the same happens with the sql-group.

Please advise how I could insert the data as received without conversion.

Thanks

Sajeewa @ ispONE

==================================================================

Wed May 27 09:19:48 2009 : Info: FreeRADIUS Version 2.0.4, for host 
i486-pc-linux-gnu, built on Sep  7 2008 at 23:35:34
Wed May 27 09:19:48 2009 : Info: Copyright (C) 1999-2008 The FreeRADIUS 
server project and contributors.
Wed May 27 09:19:48 2009 : Info: There is NO warranty; not even for 
MERCHANTABILITY or FITNESS FOR A
Wed May 27 09:19:48 2009 : Info: PARTICULAR PURPOSE.
Wed May 27 09:19:48 2009 : Info: You may redistribute copies of FreeRADIUS 
under the terms of the
Wed May 27 09:19:48 2009 : Info: GNU General Public License.
Wed May 27 09:19:48 2009 : Info: Starting - reading configuration files 
...
Wed May 27 09:19:48 2009 : Debug: including configuration file 
/etc/freeradius/radiusd_dial.conf
Wed May 27 09:19:48 2009 : Debug: including configuration file 
/etc/freeradius/proxy_dial.conf
Wed May 27 09:19:48 2009 : Debug: including configuration file 
/etc/freeradius/clients_dial.conf
Wed May 27 09:19:48 2009 : Debug: including configuration file 
/etc/freeradius/sql_dial.conf
Wed May 27 09:19:48 2009 : Debug: including configuration file 
/etc/freeradius/sql_prepaid_counter.conf
Wed May 27 09:19:48 2009 : Debug: including configuration file 
/etc/freeradius/policy.conf
Wed May 27 09:19:48 2009 : Debug: including files in directory 
/etc/freeradius/sites-enabled/
Wed May 27 09:19:48 2009 : Debug: including configuration file 
/etc/freeradius/sites-enabled/default_dial
Wed May 27 09:19:48 2009 : Debug: including dictionary file 
/etc/freeradius/dictionary
Wed May 27 09:19:48 2009 : Debug: main {
Wed May 27 09:19:48 2009 : Debug:       prefix = "/usr"
Wed May 27 09:19:48 2009 : Debug:       localstatedir = "/var"
Wed May 27 09:19:48 2009 : Debug:       logdir = "/var/log/freeradius"
Wed May 27 09:19:48 2009 : Debug:       libdir = "/usr/lib/freeradius"
Wed May 27 09:19:48 2009 : Debug:       radacctdir = 
"/var/log/freeradius/radacct"
Wed May 27 09:19:48 2009 : Debug:       hostname_lookups = no
Wed May 27 09:19:48 2009 : Debug:       max_request_time = 30
Wed May 27 09:19:48 2009 : Debug:       cleanup_delay = 5
Wed May 27 09:19:48 2009 : Debug:       max_requests = 1024
Wed May 27 09:19:48 2009 : Debug:       allow_core_dumps = no
Wed May 27 09:19:48 2009 : Debug:       pidfile = 
"/var/run/freeradius/freeradius_dial.pid"
Wed May 27 09:19:48 2009 : Debug:       user = "freerad"
Wed May 27 09:19:48 2009 : Debug:       group = "freerad"
Wed May 27 09:19:48 2009 : Debug:       checkrad = "/usr/sbin/checkrad"
Wed May 27 09:19:48 2009 : Debug:       debug_level = 0
Wed May 27 09:19:48 2009 : Debug:       proxy_requests = yes
Wed May 27 09:19:48 2009 : Debug:  security {
Wed May 27 09:19:48 2009 : Debug:       max_attributes = 200
Wed May 27 09:19:48 2009 : Debug:       reject_delay = 0
Wed May 27 09:19:48 2009 : Debug:       status_server = yes
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug: }
Wed May 27 09:19:48 2009 : Debug:  client 144.130.4.5 {
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 144.130.4.5
Wed May 27 09:19:48 2009 : Debug:       require_message_authenticator = no
Wed May 27 09:19:48 2009 : Debug:       secret = "11oneONEV6"
Wed May 27 09:19:48 2009 : Debug:       shortname = "telstra-1"
Wed May 27 09:19:48 2009 : Debug:       nastype = "other"
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  client 144.130.7.5 {
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 144.130.7.5
Wed May 27 09:19:48 2009 : Debug:       require_message_authenticator = no
Wed May 27 09:19:48 2009 : Debug:       secret = "11oneONEV6"
Wed May 27 09:19:48 2009 : Debug:       shortname = "telstra-2"
Wed May 27 09:19:48 2009 : Debug:       nastype = "other"
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  client 192.168.0.19 {
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 192.168.0.19
Wed May 27 09:19:48 2009 : Debug:       require_message_authenticator = no
Wed May 27 09:19:48 2009 : Debug:       secret = "11oneONEV6"
Wed May 27 09:19:48 2009 : Debug:       shortname = "test-1"
Wed May 27 09:19:48 2009 : Debug:       nastype = "other"
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  client 192.168.0.212 {
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 192.168.0.212
Wed May 27 09:19:48 2009 : Debug:       require_message_authenticator = no
Wed May 27 09:19:48 2009 : Debug:       secret = "secret"
Wed May 27 09:19:48 2009 : Debug:       shortname = "test-2"
Wed May 27 09:19:48 2009 : Debug:       nastype = "other"
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  client 192.168.0.151 {
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 192.168.0.151
Wed May 27 09:19:48 2009 : Debug:       require_message_authenticator = no
Wed May 27 09:19:48 2009 : Debug:       secret = "secret"
Wed May 27 09:19:48 2009 : Debug:       shortname = "test-3"
Wed May 27 09:19:48 2009 : Debug:       nastype = "other"
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug: radiusd_dial: #### Loading Realms and 
Home Servers ####
Wed May 27 09:19:48 2009 : Debug:  proxy server {
Wed May 27 09:19:48 2009 : Debug:       retry_delay = 5
Wed May 27 09:19:48 2009 : Debug:       retry_count = 3
Wed May 27 09:19:48 2009 : Debug:       default_fallback = no
Wed May 27 09:19:48 2009 : Debug:       dead_time = 120
Wed May 27 09:19:48 2009 : Debug:       wake_all_if_all_dead = no
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server hugonet_1 {
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 114.111.142.98
Wed May 27 09:19:48 2009 : Debug:       port = 1813
Wed May 27 09:19:48 2009 : Debug:       type = "acct"
Wed May 27 09:19:48 2009 : Debug:       secret = "w89100kwq"
Wed May 27 09:19:48 2009 : Debug:       response_window = 20
Wed May 27 09:19:48 2009 : Debug:       max_outstanding = 65536
Wed May 27 09:19:48 2009 : Debug:       zombie_period = 40
Wed May 27 09:19:48 2009 : Debug:       status_check = "request"
Wed May 27 09:19:48 2009 : Debug:       ping_check = "none"
Wed May 27 09:19:48 2009 : Debug:       ping_interval = 30
Wed May 27 09:19:48 2009 : Debug:       check_interval = 30
Wed May 27 09:19:48 2009 : Debug:       num_answers_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       num_pings_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       revive_interval = 300
Wed May 27 09:19:48 2009 : Debug:       status_check_timeout = 4
Wed May 27 09:19:48 2009 : Debug:       username = 
"statuscheck@ispone.com.au"
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server_pool hugonet_failover {
Wed May 27 09:19:48 2009 : Debug:       type = fail-over
Wed May 27 09:19:48 2009 : Debug:       home_server = hugonet_1
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  realm hugonet.com.au {
Wed May 27 09:19:48 2009 : Debug:       acct_pool = hugonet_failover
Wed May 27 09:19:48 2009 : Debug:       nostrip
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server planetisp_1 {
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 210.50.6.202
Wed May 27 09:19:48 2009 : Debug:       port = 1646
Wed May 27 09:19:48 2009 : Debug:       type = "acct"
Wed May 27 09:19:48 2009 : Debug:       secret = "62gys8j"
Wed May 27 09:19:48 2009 : Debug:       response_window = 20
Wed May 27 09:19:48 2009 : Debug:       max_outstanding = 65536
Wed May 27 09:19:48 2009 : Debug:       zombie_period = 40
Wed May 27 09:19:48 2009 : Debug:       status_check = "request"
Wed May 27 09:19:48 2009 : Debug:       ping_check = "none"
Wed May 27 09:19:48 2009 : Debug:       ping_interval = 30
Wed May 27 09:19:48 2009 : Debug:       check_interval = 30
Wed May 27 09:19:48 2009 : Debug:       num_answers_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       num_pings_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       revive_interval = 300
Wed May 27 09:19:48 2009 : Debug:       status_check_timeout = 4
Wed May 27 09:19:48 2009 : Debug:       username = 
"statuscheck@ispone.com.au"
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server_pool planetisp_failover {
Wed May 27 09:19:48 2009 : Debug:       type = fail-over
Wed May 27 09:19:48 2009 : Debug:       home_server = planetisp_1
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  realm planetisp.com.au {
Wed May 27 09:19:48 2009 : Debug:       acct_pool = planetisp_failover
Wed May 27 09:19:48 2009 : Debug:       nostrip
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  realm 21century.com.au {
Wed May 27 09:19:48 2009 : Debug:       acct_pool = planetisp_failover
Wed May 27 09:19:48 2009 : Debug:       nostrip
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  realm computersmobile.com.au {
Wed May 27 09:19:48 2009 : Debug:       acct_pool = planetisp_failover
Wed May 27 09:19:48 2009 : Debug:       nostrip
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server tecknowlogy_1 {
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 202.125.168.246
Wed May 27 09:19:48 2009 : Debug:       port = 1813
Wed May 27 09:19:48 2009 : Debug:       type = "acct"
Wed May 27 09:19:48 2009 : Debug:       secret = "2rtYhamfG"
Wed May 27 09:19:48 2009 : Debug:       response_window = 20
Wed May 27 09:19:48 2009 : Debug:       max_outstanding = 65536
Wed May 27 09:19:48 2009 : Debug:       zombie_period = 40
Wed May 27 09:19:48 2009 : Debug:       status_check = "request"
Wed May 27 09:19:48 2009 : Debug:       ping_check = "none"
Wed May 27 09:19:48 2009 : Debug:       ping_interval = 30
Wed May 27 09:19:48 2009 : Debug:       check_interval = 30
Wed May 27 09:19:48 2009 : Debug:       num_answers_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       num_pings_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       revive_interval = 300
Wed May 27 09:19:48 2009 : Debug:       status_check_timeout = 4
Wed May 27 09:19:48 2009 : Debug:       username = 
"statuscheck@ispone.com.au"
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server_pool tecknowlogy_failover {
Wed May 27 09:19:48 2009 : Debug:       type = fail-over
Wed May 27 09:19:48 2009 : Debug:       home_server = tecknowlogy_1
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  realm rtele.com.au {
Wed May 27 09:19:48 2009 : Debug:       acct_pool = tecknowlogy_failover
Wed May 27 09:19:48 2009 : Debug:       nostrip
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server waterfront_1 {
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 203.123.80.196
Wed May 27 09:19:48 2009 : Debug:       port = 1813
Wed May 27 09:19:48 2009 : Debug:       type = "acct"
Wed May 27 09:19:48 2009 : Debug:       secret = "tkwuIm278va"
Wed May 27 09:19:48 2009 : Debug:       response_window = 20
Wed May 27 09:19:48 2009 : Debug:       max_outstanding = 65536
Wed May 27 09:19:48 2009 : Debug:       zombie_period = 40
Wed May 27 09:19:48 2009 : Debug:       status_check = "request"
Wed May 27 09:19:48 2009 : Debug:       ping_check = "none"
Wed May 27 09:19:48 2009 : Debug:       ping_interval = 30
Wed May 27 09:19:48 2009 : Debug:       check_interval = 30
Wed May 27 09:19:48 2009 : Debug:       num_answers_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       num_pings_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       revive_interval = 300
Wed May 27 09:19:48 2009 : Debug:       status_check_timeout = 4
Wed May 27 09:19:48 2009 : Debug:       username = 
"statuscheck@ispone.com.au"
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server_pool waterfront_failover {
Wed May 27 09:19:48 2009 : Debug:       type = fail-over
Wed May 27 09:19:48 2009 : Debug:       home_server = waterfront_1
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  realm waterfront.net.au {
Wed May 27 09:19:48 2009 : Debug:       acct_pool = waterfront_failover
Wed May 27 09:19:48 2009 : Debug:       nostrip
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server beagle_1 {
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 202.4.231.249
Wed May 27 09:19:48 2009 : Debug:       port = 1813
Wed May 27 09:19:48 2009 : Debug:       type = "acct"
Wed May 27 09:19:48 2009 : Debug:       secret = "tkwuIm278va"
Wed May 27 09:19:48 2009 : Debug:       response_window = 20
Wed May 27 09:19:48 2009 : Debug:       max_outstanding = 65536
Wed May 27 09:19:48 2009 : Debug:       zombie_period = 40
Wed May 27 09:19:48 2009 : Debug:       status_check = "request"
Wed May 27 09:19:48 2009 : Debug:       ping_check = "none"
Wed May 27 09:19:48 2009 : Debug:       ping_interval = 30
Wed May 27 09:19:48 2009 : Debug:       check_interval = 30
Wed May 27 09:19:48 2009 : Debug:       num_answers_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       num_pings_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       revive_interval = 300
Wed May 27 09:19:48 2009 : Debug:       status_check_timeout = 4
Wed May 27 09:19:48 2009 : Debug:       username = 
"statuscheck@ispone.com.au"
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server_pool beagle_failover {
Wed May 27 09:19:48 2009 : Debug:       type = fail-over
Wed May 27 09:19:48 2009 : Debug:       home_server = beagle_1
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  realm beagle.com.au {
Wed May 27 09:19:48 2009 : Debug:       acct_pool = beagle_failover
Wed May 27 09:19:48 2009 : Debug:       nostrip
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server summit_1 {
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 203.94.170.204
Wed May 27 09:19:48 2009 : Debug:       port = 1646
Wed May 27 09:19:48 2009 : Debug:       type = "acct"
Wed May 27 09:19:48 2009 : Debug:       secret = "b92e1e3ab274"
Wed May 27 09:19:48 2009 : Debug:       response_window = 20
Wed May 27 09:19:48 2009 : Debug:       max_outstanding = 65536
Wed May 27 09:19:48 2009 : Debug:       zombie_period = 40
Wed May 27 09:19:48 2009 : Debug:       status_check = "request"
Wed May 27 09:19:48 2009 : Debug:       ping_check = "none"
Wed May 27 09:19:48 2009 : Debug:       ping_interval = 30
Wed May 27 09:19:48 2009 : Debug:       check_interval = 30
Wed May 27 09:19:48 2009 : Debug:       num_answers_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       num_pings_to_alive = 3
Wed May 27 09:19:48 2009 : Debug:       revive_interval = 300
Wed May 27 09:19:48 2009 : Debug:       status_check_timeout = 4
Wed May 27 09:19:48 2009 : Debug:       username = 
"statuscheck@ispone.com.au"
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  home_server_pool summit_failover {
Wed May 27 09:19:48 2009 : Debug:       type = fail-over
Wed May 27 09:19:48 2009 : Debug:       home_server = summit_1
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  realm summit.net.au {
Wed May 27 09:19:48 2009 : Debug:       acct_pool = summit_failover
Wed May 27 09:19:48 2009 : Debug:       nostrip
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug:  realm DEFAULT {
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug: radiusd_dial: #### Instantiating modules 
####
Wed May 27 09:19:48 2009 : Debug:  instantiate {
Wed May 27 09:19:48 2009 : Debug:     (Loaded rlm_exec, checking if it's 
valid)
Wed May 27 09:19:48 2009 : Debug:  Module: Linked to module rlm_exec
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating echo
Wed May 27 09:19:48 2009 : Debug:   exec echo {
Wed May 27 09:19:48 2009 : Debug:       wait = yes
Wed May 27 09:19:48 2009 : Debug:       program = "/bin/echo %{User-Name}"
Wed May 27 09:19:48 2009 : Debug:       input_pairs = "request"
Wed May 27 09:19:48 2009 : Debug:       output_pairs = "reply"
Wed May 27 09:19:48 2009 : Debug:       packet_type = "Access-Reject"
Wed May 27 09:19:48 2009 : Debug:       shell_escape = yes
Wed May 27 09:19:48 2009 : Debug:   }
Wed May 27 09:19:48 2009 : Debug:     (Loaded rlm_expr, checking if it's 
valid)
Wed May 27 09:19:48 2009 : Debug:  Module: Linked to module rlm_expr
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating expr
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug: radiusd_dial: #### Loading Virtual 
Servers ####
Wed May 27 09:19:48 2009 : Debug: server {
Wed May 27 09:19:48 2009 : Debug:  modules {
Wed May 27 09:19:48 2009 : Debug:  Module: Checking authenticate {...} for 
more modules to load
Wed May 27 09:19:48 2009 : Debug:     (Loaded rlm_pap, checking if it's 
valid)
Wed May 27 09:19:48 2009 : Debug:  Module: Linked to module rlm_pap
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating pap
Wed May 27 09:19:48 2009 : Debug:   pap {
Wed May 27 09:19:48 2009 : Debug:       encryption_scheme = "auto"
Wed May 27 09:19:48 2009 : Debug:       auto_header = no
Wed May 27 09:19:48 2009 : Debug:   }
Wed May 27 09:19:48 2009 : Debug:     (Loaded rlm_chap, checking if it's 
valid)
Wed May 27 09:19:48 2009 : Debug:  Module: Linked to module rlm_chap
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating chap
Wed May 27 09:19:48 2009 : Debug:  Module: Checking authorize {...} for 
more modules to load
Wed May 27 09:19:48 2009 : Debug:     (Loaded rlm_preprocess, checking if 
it's valid)
Wed May 27 09:19:48 2009 : Debug:  Module: Linked to module rlm_preprocess
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating preprocess
Wed May 27 09:19:48 2009 : Debug:   preprocess {
Wed May 27 09:19:48 2009 : Debug:       huntgroups = 
"/etc/freeradius/huntgroups_dial"
Wed May 27 09:19:48 2009 : Debug:       hints = 
"/etc/freeradius/hints_dial"
Wed May 27 09:19:48 2009 : Debug:       with_ascend_hack = no
Wed May 27 09:19:48 2009 : Debug:       ascend_channels_per_line = 23
Wed May 27 09:19:48 2009 : Debug:       with_ntdomain_hack = no
Wed May 27 09:19:48 2009 : Debug:       with_specialix_jetstream_hack = no
Wed May 27 09:19:48 2009 : Debug:       with_cisco_vsa_hack = no
Wed May 27 09:19:48 2009 : Debug:       with_alvarion_vsa_hack = no
Wed May 27 09:19:48 2009 : Debug:   }
Wed May 27 09:19:48 2009 : Debug:     (Loaded rlm_realm, checking if it's 
valid)
Wed May 27 09:19:48 2009 : Debug:  Module: Linked to module rlm_realm
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating suffix
Wed May 27 09:19:48 2009 : Debug:   realm suffix {
Wed May 27 09:19:48 2009 : Debug:       format = "suffix"
Wed May 27 09:19:48 2009 : Debug:       delimiter = "@"
Wed May 27 09:19:48 2009 : Debug:       ignore_default = no
Wed May 27 09:19:48 2009 : Debug:       ignore_null = no
Wed May 27 09:19:48 2009 : Debug:   }
Wed May 27 09:19:48 2009 : Debug:     (Loaded rlm_sql, checking if it's 
valid)
Wed May 27 09:19:48 2009 : Debug:  Module: Linked to module rlm_sql
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating auth_1
Wed May 27 09:19:48 2009 : Debug:   sql auth_1 {
Wed May 27 09:19:48 2009 : Debug:       driver = "rlm_sql_mysql"
Wed May 27 09:19:48 2009 : Debug:       server = "localhost"
Wed May 27 09:19:48 2009 : Debug:       port = ""
Wed May 27 09:19:48 2009 : Debug:       login = "dial_radius"
Wed May 27 09:19:48 2009 : Debug:       password = "radius912m87"
Wed May 27 09:19:48 2009 : Debug:       radius_db = "Radius"
Wed May 27 09:19:48 2009 : Debug:       read_groups = yes
Wed May 27 09:19:48 2009 : Debug:       sqltrace = no
Wed May 27 09:19:48 2009 : Debug:       sqltracefile = 
"/var/log/freeradius/sqltrace_dial.sql"
Wed May 27 09:19:48 2009 : Debug:       readclients = no
Wed May 27 09:19:48 2009 : Debug:       deletestalesessions = yes
Wed May 27 09:19:48 2009 : Debug:       num_sql_socks = 5
Wed May 27 09:19:48 2009 : Debug:       sql_user_name = ""
Wed May 27 09:19:48 2009 : Debug:       default_user_profile = ""
Wed May 27 09:19:48 2009 : Debug:       nas_query = "SELECT 
id,nasname,shortname,type,secret FROM nas"
Wed May 27 09:19:48 2009 : Debug:       authorize_check_query = "SELECT 
id, username, attribute, value, op FROM radcheck WHERE username = 
'%{User-Name}' ORDER BY id"
Wed May 27 09:19:48 2009 : Debug:       authorize_reply_query = "SELECT 
id, username, attribute, value, op FROM radreply WHERE username = 
'%{User-Name}' ORDER BY id"
Wed May 27 09:19:48 2009 : Debug:       authorize_group_check_query = 
"SELECT id, groupname, attribute, value, op FROM radgroupcheck WHERE 
groupname = '%{Sql-Group}' ORDER BY id"
Wed May 27 09:19:48 2009 : Debug:       authorize_group_reply_query = 
"SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE 
groupname = '%{Sql-Group}' ORDER BY id"
Wed May 27 09:19:48 2009 : Debug:       accounting_onoff_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_update_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_update_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_start_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_start_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_stop_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_stop_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       group_membership_query = "SELECT 
groupname FROM radusergroup WHERE username = '%{User-Name}' ORDER BY 
priority"
Wed May 27 09:19:48 2009 : Debug:       connect_failure_retry_delay = 10
Wed May 27 09:19:48 2009 : Debug:       simul_count_query = ""
Wed May 27 09:19:48 2009 : Debug:       simul_verify_query = "SELECT 
ACCTSESSIONID, USERNAME, NASIDENTIFIER, NASPORT, FRAMEDIPADDRESS, 
CALLINGSTATIONID, SERVICETYPE FROM RADONLINE WHERE USERNAME = 
'%{User-Name}'"
Wed May 27 09:19:48 2009 : Debug:       postauth_query = ""
Wed May 27 09:19:48 2009 : Debug:       safe-characters = 
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Wed May 27 09:19:48 2009 : Debug:   }
Wed May 27 09:19:48 2009 : Info: rlm_sql (auth_1): Driver rlm_sql_mysql 
(module rlm_sql_mysql) loaded and linked
Wed May 27 09:19:48 2009 : Info: rlm_sql (auth_1): Attempting to connect 
to dial_radius@localhost:/Radius
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): starting 0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): Attempting to connect 
rlm_sql_mysql #0
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): Connected new DB 
handle, #0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): starting 1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): Attempting to connect 
rlm_sql_mysql #1
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): Connected new DB 
handle, #1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): starting 2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): Attempting to connect 
rlm_sql_mysql #2
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): Connected new DB 
handle, #2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): starting 3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): Attempting to connect 
rlm_sql_mysql #3
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): Connected new DB 
handle, #3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): starting 4
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): Attempting to connect 
rlm_sql_mysql #4
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #4
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_1): Connected new DB 
handle, #4
Wed May 27 09:19:48 2009 : Debug:     (Loaded rlm_sqlcounter, checking if 
it's valid)
Wed May 27 09:19:48 2009 : Debug:  Module: Linked to module rlm_sqlcounter
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating 
dial_prepaid_counter
Wed May 27 09:19:48 2009 : Debug:   sqlcounter dial_prepaid_counter {
Wed May 27 09:19:48 2009 : Debug:       counter-name = 
"Max-All-Session-Time"
Wed May 27 09:19:48 2009 : Debug:       check-name = "Max-All-Session"
Wed May 27 09:19:48 2009 : Debug:       key = "User-Name"
Wed May 27 09:19:48 2009 : Debug:       sqlmod-inst = "prepaid"
Wed May 27 09:19:48 2009 : Debug:       query = "SELECT SESSIONTIMEUSED 
FROM PREPAIDDIALUPTIME WHERE USERNAME = '%{%k}'"
Wed May 27 09:19:48 2009 : Debug:       reset = "never"
Wed May 27 09:19:48 2009 : Debug:       safe-characters = 
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Wed May 27 09:19:48 2009 : Debug:   }
Wed May 27 09:19:48 2009 : Debug: rlm_sqlcounter: Reply attribute set to 
Session-Timeout.
Wed May 27 09:19:48 2009 : Debug: rlm_sqlcounter: Counter attribute 
Max-All-Session-Time is number 11273
Wed May 27 09:19:48 2009 : Debug: rlm_sqlcounter: Check attribute 
Max-All-Session is number 11274
Wed May 27 09:19:48 2009 : Debug: rlm_sqlcounter: Current Time: 1243379988 
[2009-05-27 09:19:48], Next reset 0 [2009-05-27 09:00:00]
Wed May 27 09:19:48 2009 : Debug: rlm_sqlcounter: Current Time: 1243379988 
[2009-05-27 09:19:48], Prev reset 0 [2009-05-27 09:00:00]
Wed May 27 09:19:48 2009 : Debug:  Module: Checking preacct {...} for more 
modules to load
Wed May 27 09:19:48 2009 : Debug:  Module: Checking accounting {...} for 
more modules to load
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating accounting_1
Wed May 27 09:19:48 2009 : Debug:   sql accounting_1 {
Wed May 27 09:19:48 2009 : Debug:       driver = "rlm_sql_mysql"
Wed May 27 09:19:48 2009 : Debug:       server = "localhost"
Wed May 27 09:19:48 2009 : Debug:       port = ""
Wed May 27 09:19:48 2009 : Debug:       login = "dial_radius"
Wed May 27 09:19:48 2009 : Debug:       password = "radius912m87"
Wed May 27 09:19:48 2009 : Debug:       radius_db = "Radius"
Wed May 27 09:19:48 2009 : Debug:       read_groups = yes
Wed May 27 09:19:48 2009 : Debug:       sqltrace = no
Wed May 27 09:19:48 2009 : Debug:       sqltracefile = 
"/var/log/freeradius/sqltrace_dial.sql"
Wed May 27 09:19:48 2009 : Debug:       readclients = no
Wed May 27 09:19:48 2009 : Debug:       deletestalesessions = yes
Wed May 27 09:19:48 2009 : Debug:       num_sql_socks = 5
Wed May 27 09:19:48 2009 : Debug:       sql_user_name = ""
Wed May 27 09:19:48 2009 : Debug:       default_user_profile = ""
Wed May 27 09:19:48 2009 : Debug:       nas_query = "SELECT 
id,nasname,shortname,type,secret FROM nas"
Wed May 27 09:19:48 2009 : Debug:       authorize_check_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_reply_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_group_check_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_group_reply_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_onoff_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_update_query = "INSERT 
DELAYED INTO RADUSAGE_%Y%m (USERNAME, TIME_STAMP, ACCTSTATUSTYPE, 
ACCTDELAYTIME, ACCTINPUTOCTETS, ACCTOUTPUTOCTETS, ACCTSESSIONID, 
ACCTSESSIONTIME, ACCTTERMINATECAUSE, FRAMEDIPADDRESS, NASIDENTIFIER, 
NASPORT, DNIS, CALLINGSTATIONID, CALLZONE) VALUES 
('%{User-Name}','%T','3','%{Acct-Delay-Time}','%{Acct-Input-Octets}','%{Acct-Output-Octets}','%{Acct-Session-Id}','%{Acct-Session-Time}','%{Ascend-Disconnect-Cause}','%{Framed-IP-Address}','%{NAS-IP-Address}','%{NAS-Port}','%{Called-Station-Id}','%{Calling-Station-Id}','%{X-Ascend-Billing-Number}')"
Wed May 27 09:19:48 2009 : Debug:       accounting_update_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_start_query = "INSERT 
DELAYED INTO RADUSAGE_%Y%m (USERNAME, TIME_STAMP, ACCTSTATUSTYPE, 
ACCTDELAYTIME, ACCTINPUTOCTETS, ACCTOUTPUTOCTETS, ACCTSESSIONID, 
ACCTSESSIONTIME, ACCTTERMINATECAUSE, FRAMEDIPADDRESS, NASIDENTIFIER, 
NASPORT, DNIS, CALLINGSTATIONID, CALLZONE) VALUES 
('%{User-Name}','%T','1','%{Acct-Delay-Time}','%{Acct-Input-Octets}','%{Acct-Output-Octets}','%{Acct-Session-Id}','%{Acct-Session-Time}','%{Ascend-Disconnect-Cause}','%{Framed-IP-Address}','%{NAS-IP-Address}','%{NAS-Port}','%{Called-Station-Id}','%{Calling-Station-Id}','%{X-Ascend-Billing-Number}')"
Wed May 27 09:19:48 2009 : Debug:       accounting_start_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_stop_query = "INSERT 
DELAYED INTO RADUSAGE_%Y%m (USERNAME, TIME_STAMP, ACCTSTATUSTYPE, 
ACCTDELAYTIME, ACCTINPUTOCTETS, ACCTOUTPUTOCTETS, ACCTSESSIONID, 
ACCTSESSIONTIME, ACCTTERMINATECAUSE, FRAMEDIPADDRESS, NASIDENTIFIER, 
NASPORT, DNIS, CALLINGSTATIONID, CALLZONE) VALUES 
('%{User-Name}','%T','2','%{Acct-Delay-Time}','%{Acct-Input-Octets}','%{Acct-Output-Octets}','%{Acct-Session-Id}','%{Acct-Session-Time}','%{Ascend-Disconnect-Cause}','%{Framed-IP-Address}','%{NAS-IP-Address}','%{NAS-Port}','%{Called-Station-Id}','%{Calling-Station-Id}','%{X-Ascend-Billing-Number}')"
Wed May 27 09:19:48 2009 : Debug:       accounting_stop_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       connect_failure_retry_delay = 10
Wed May 27 09:19:48 2009 : Debug:       simul_count_query = ""
Wed May 27 09:19:48 2009 : Debug:       simul_verify_query = ""
Wed May 27 09:19:48 2009 : Debug:       postauth_query = ""
Wed May 27 09:19:48 2009 : Debug:       safe-characters = 
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Wed May 27 09:19:48 2009 : Debug:   }
Wed May 27 09:19:48 2009 : Info: rlm_sql (accounting_1): Driver 
rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
Wed May 27 09:19:48 2009 : Info: rlm_sql (accounting_1): Attempting to 
connect to dial_radius@localhost:/Radius
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): starting 0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): Attempting to 
connect rlm_sql_mysql #0
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): Connected new DB 
handle, #0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): starting 1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): Attempting to 
connect rlm_sql_mysql #1
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): Connected new DB 
handle, #1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): starting 2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): Attempting to 
connect rlm_sql_mysql #2
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): Connected new DB 
handle, #2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): starting 3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): Attempting to 
connect rlm_sql_mysql #3
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): Connected new DB 
handle, #3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): starting 4
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): Attempting to 
connect rlm_sql_mysql #4
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #4
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_1): Connected new DB 
handle, #4
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating accounting_2
Wed May 27 09:19:48 2009 : Debug:   sql accounting_2 {
Wed May 27 09:19:48 2009 : Debug:       driver = "rlm_sql_mysql"
Wed May 27 09:19:48 2009 : Debug:       server = "localhost"
Wed May 27 09:19:48 2009 : Debug:       port = ""
Wed May 27 09:19:48 2009 : Debug:       login = "dial_radius"
Wed May 27 09:19:48 2009 : Debug:       password = "radius912m87"
Wed May 27 09:19:48 2009 : Debug:       radius_db = "Radius"
Wed May 27 09:19:48 2009 : Debug:       read_groups = yes
Wed May 27 09:19:48 2009 : Debug:       sqltrace = no
Wed May 27 09:19:48 2009 : Debug:       sqltracefile = 
"/var/log/freeradius/sqltrace_dial.sql"
Wed May 27 09:19:48 2009 : Debug:       readclients = no
Wed May 27 09:19:48 2009 : Debug:       deletestalesessions = yes
Wed May 27 09:19:48 2009 : Debug:       num_sql_socks = 5
Wed May 27 09:19:48 2009 : Debug:       sql_user_name = ""
Wed May 27 09:19:48 2009 : Debug:       default_user_profile = ""
Wed May 27 09:19:48 2009 : Debug:       nas_query = "SELECT 
id,nasname,shortname,type,secret FROM nas"
Wed May 27 09:19:48 2009 : Debug:       authorize_check_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_reply_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_group_check_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_group_reply_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_onoff_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_update_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_update_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_start_query = "INSERT 
INTO RADONLINE (USERNAME, NASIDENTIFIER, NASPORT, ACCTSESSIONID, 
TIME_STAMP, FRAMEDIPADDRESS, NASPORTTYPE, SERVICETYPE, CALLINGSTATIONID, 
CALLEDSTATIONID, CALLZONE) VALUES ('%{User-Name}', '%{NAS-IP-Address}', 
'%{NAS-Port}', '%{Acct-Session-Id}', '%T', '%{Framed-IP-Address}', 
'0%{NAS-Port-Type}', '%{Service-Type}', '%{Calling-Station-Id}', 
'%{Called-Station-Id}', '%{X-Ascend-Billing-Number}')"
Wed May 27 09:19:48 2009 : Debug:       accounting_start_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_stop_query = "DELETE 
FROM RADONLINE WHERE USERNAME = '%{User-Name}' AND NASIDENTIFIER = 
'%{NAS-IP-Address}' AND NASPORT = '%{NAS-Port}'"
Wed May 27 09:19:48 2009 : Debug:       accounting_stop_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       connect_failure_retry_delay = 10
Wed May 27 09:19:48 2009 : Debug:       simul_count_query = ""
Wed May 27 09:19:48 2009 : Debug:       simul_verify_query = ""
Wed May 27 09:19:48 2009 : Debug:       postauth_query = ""
Wed May 27 09:19:48 2009 : Debug:       safe-characters = 
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Wed May 27 09:19:48 2009 : Debug:   }
Wed May 27 09:19:48 2009 : Info: rlm_sql (accounting_2): Driver 
rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
Wed May 27 09:19:48 2009 : Info: rlm_sql (accounting_2): Attempting to 
connect to dial_radius@localhost:/Radius
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): starting 0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): Attempting to 
connect rlm_sql_mysql #0
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): Connected new DB 
handle, #0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): starting 1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): Attempting to 
connect rlm_sql_mysql #1
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): Connected new DB 
handle, #1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): starting 2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): Attempting to 
connect rlm_sql_mysql #2
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): Connected new DB 
handle, #2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): starting 3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): Attempting to 
connect rlm_sql_mysql #3
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): Connected new DB 
handle, #3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): starting 4
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): Attempting to 
connect rlm_sql_mysql #4
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #4
Wed May 27 09:19:48 2009 : Debug: rlm_sql (accounting_2): Connected new DB 
handle, #4
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating prepaid
Wed May 27 09:19:48 2009 : Debug:   sql prepaid {
Wed May 27 09:19:48 2009 : Debug:       driver = "rlm_sql_mysql"
Wed May 27 09:19:48 2009 : Debug:       server = "localhost"
Wed May 27 09:19:48 2009 : Debug:       port = ""
Wed May 27 09:19:48 2009 : Debug:       login = "dial_radius"
Wed May 27 09:19:48 2009 : Debug:       password = "radius912m87"
Wed May 27 09:19:48 2009 : Debug:       radius_db = "Radius"
Wed May 27 09:19:48 2009 : Debug:       read_groups = yes
Wed May 27 09:19:48 2009 : Debug:       sqltrace = no
Wed May 27 09:19:48 2009 : Debug:       sqltracefile = 
"/var/log/freeradius/sqltrace_dial.sql"
Wed May 27 09:19:48 2009 : Debug:       readclients = no
Wed May 27 09:19:48 2009 : Debug:       deletestalesessions = yes
Wed May 27 09:19:48 2009 : Debug:       num_sql_socks = 5
Wed May 27 09:19:48 2009 : Debug:       sql_user_name = ""
Wed May 27 09:19:48 2009 : Debug:       default_user_profile = ""
Wed May 27 09:19:48 2009 : Debug:       nas_query = "SELECT 
id,nasname,shortname,type,secret FROM nas"
Wed May 27 09:19:48 2009 : Debug:       authorize_check_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_reply_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_group_check_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_group_reply_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_onoff_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_update_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_update_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_start_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_start_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_stop_query = "UPDATE 
PREPAIDDIALUPTIME SET SESSIONTIMEUSED = (SESSIONTIMEUSED + 
%{Acct-Session-Time}) WHERE USERNAME = '%{User-Name}'"
Wed May 27 09:19:48 2009 : Debug:       accounting_stop_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       connect_failure_retry_delay = 10
Wed May 27 09:19:48 2009 : Debug:       simul_count_query = ""
Wed May 27 09:19:48 2009 : Debug:       simul_verify_query = ""
Wed May 27 09:19:48 2009 : Debug:       postauth_query = ""
Wed May 27 09:19:48 2009 : Debug:       safe-characters = 
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Wed May 27 09:19:48 2009 : Debug:   }
Wed May 27 09:19:48 2009 : Info: rlm_sql (prepaid): Driver rlm_sql_mysql 
(module rlm_sql_mysql) loaded and linked
Wed May 27 09:19:48 2009 : Info: rlm_sql (prepaid): Attempting to connect 
to dial_radius@localhost:/Radius
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): starting 0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): Attempting to connect 
rlm_sql_mysql #0
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): Connected new DB 
handle, #0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): starting 1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): Attempting to connect 
rlm_sql_mysql #1
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): Connected new DB 
handle, #1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): starting 2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): Attempting to connect 
rlm_sql_mysql #2
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): Connected new DB 
handle, #2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): starting 3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): Attempting to connect 
rlm_sql_mysql #3
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): Connected new DB 
handle, #3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): starting 4
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): Attempting to connect 
rlm_sql_mysql #4
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #4
Wed May 27 09:19:48 2009 : Debug: rlm_sql (prepaid): Connected new DB 
handle, #4
Wed May 27 09:19:48 2009 : Debug:  Module: Checking session {...} for more 
modules to load
Wed May 27 09:19:48 2009 : Debug:  Module: Checking post-auth {...} for 
more modules to load
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating auth_reject
Wed May 27 09:19:48 2009 : Debug:   sql auth_reject {
Wed May 27 09:19:48 2009 : Debug:       driver = "rlm_sql_mysql"
Wed May 27 09:19:48 2009 : Debug:       server = "localhost"
Wed May 27 09:19:48 2009 : Debug:       port = ""
Wed May 27 09:19:48 2009 : Debug:       login = "dial_radius"
Wed May 27 09:19:48 2009 : Debug:       password = "radius912m87"
Wed May 27 09:19:48 2009 : Debug:       radius_db = "Radius"
Wed May 27 09:19:48 2009 : Debug:       read_groups = yes
Wed May 27 09:19:48 2009 : Debug:       sqltrace = no
Wed May 27 09:19:48 2009 : Debug:       sqltracefile = 
"/var/log/freeradius/sqltrace_dial.sql"
Wed May 27 09:19:48 2009 : Debug:       readclients = no
Wed May 27 09:19:48 2009 : Debug:       deletestalesessions = yes
Wed May 27 09:19:48 2009 : Debug:       num_sql_socks = 5
Wed May 27 09:19:48 2009 : Debug:       sql_user_name = ""
Wed May 27 09:19:48 2009 : Debug:       default_user_profile = ""
Wed May 27 09:19:48 2009 : Debug:       nas_query = "SELECT 
id,nasname,shortname,type,secret FROM nas"
Wed May 27 09:19:48 2009 : Debug:       authorize_check_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_reply_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_group_check_query = ""
Wed May 27 09:19:48 2009 : Debug:       authorize_group_reply_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_onoff_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_update_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_update_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_start_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_start_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_stop_query = ""
Wed May 27 09:19:48 2009 : Debug:       accounting_stop_query_alt = ""
Wed May 27 09:19:48 2009 : Debug:       connect_failure_retry_delay = 10
Wed May 27 09:19:48 2009 : Debug:       simul_count_query = ""
Wed May 27 09:19:48 2009 : Debug:       simul_verify_query = ""
Wed May 27 09:19:48 2009 : Debug:       postauth_query = "INSERT DELAYED 
INTO RADAUTHLOG (REASON, TIME_STAMP, TYPE, USERNAME, CALLEDSTATIONID, 
CALLINGSTATIONID, PASS_WORD, CALLZONE) values 
('%{%{Module-Failure-Message}:-%{reply:Packet-Type}}','%S','0','%{User-Name}','%{Called-Station-Id}','%{Calling-Station-Id}','%{%{User-Password}:-%{Chap-Password}}','%{Ascend-Billing-Number}')"
Wed May 27 09:19:48 2009 : Debug:       safe-characters = 
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Wed May 27 09:19:48 2009 : Debug:   }
Wed May 27 09:19:48 2009 : Info: rlm_sql (auth_reject): Driver 
rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
Wed May 27 09:19:48 2009 : Info: rlm_sql (auth_reject): Attempting to 
connect to dial_radius@localhost:/Radius
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): starting 0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): Attempting to 
connect rlm_sql_mysql #0
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): Connected new DB 
handle, #0
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): starting 1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): Attempting to 
connect rlm_sql_mysql #1
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): Connected new DB 
handle, #1
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): starting 2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): Attempting to 
connect rlm_sql_mysql #2
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): Connected new DB 
handle, #2
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): starting 3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): Attempting to 
connect rlm_sql_mysql #3
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): Connected new DB 
handle, #3
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): starting 4
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): Attempting to 
connect rlm_sql_mysql #4
Wed May 27 09:19:48 2009 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #4
Wed May 27 09:19:48 2009 : Debug: rlm_sql (auth_reject): Connected new DB 
handle, #4
Wed May 27 09:19:48 2009 : Debug:     (Loaded rlm_attr_filter, checking if 
it's valid)
Wed May 27 09:19:48 2009 : Debug:  Module: Linked to module 
rlm_attr_filter
Wed May 27 09:19:48 2009 : Debug:  Module: Instantiating 
attr_filter.access_reject
Wed May 27 09:19:48 2009 : Debug:   attr_filter attr_filter.access_reject 
{
Wed May 27 09:19:48 2009 : Debug:       attrsfile = 
"/etc/freeradius/attrs.access_reject"
Wed May 27 09:19:48 2009 : Debug:       key = "%{User-Name}"
Wed May 27 09:19:48 2009 : Debug:   }
Wed May 27 09:19:48 2009 : Debug:  }
Wed May 27 09:19:48 2009 : Debug: }
Wed May 27 09:19:48 2009 : Debug: radiusd_dial: #### Opening IP addresses 
and Ports ####
Wed May 27 09:19:48 2009 : Debug: listen {
Wed May 27 09:19:48 2009 : Debug:       type = "auth"
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 192.168.0.212
Wed May 27 09:19:48 2009 : Debug:       port = 1645
Wed May 27 09:19:48 2009 : Debug: }
Wed May 27 09:19:48 2009 : Debug: listen {
Wed May 27 09:19:48 2009 : Debug:       type = "acct"
Wed May 27 09:19:48 2009 : Debug:       ipaddr = 192.168.0.212
Wed May 27 09:19:48 2009 : Debug:       port = 1646
Wed May 27 09:19:48 2009 : Debug: }
Wed May 27 09:19:48 2009 : Debug: main {
Wed May 27 09:19:48 2009 : Debug:       snmp = no
Wed May 27 09:19:48 2009 : Debug:       smux_password = ""
Wed May 27 09:19:48 2009 : Debug:       snmp_write_access = no
Wed May 27 09:19:48 2009 : Debug: }
Wed May 27 09:19:48 2009 : Debug: Listening on authentication address 
192.168.0.212 port 1645
Wed May 27 09:19:48 2009 : Debug: Listening on accounting address 
192.168.0.212 port 1646
Wed May 27 09:19:48 2009 : Debug: Listening on proxy address 192.168.0.212 
port 1647
Wed May 27 09:19:48 2009 : Debug: Ready to process requests.
rad_recv: Accounting-Request packet from host 192.168.0.19 port 1778, 
id=1, length=164
         User-Name = "sajeewaw@isp1.net.au"
         Acct-Status-Type = Start
         NAS-Port-Type = Async
         Client-Port-Id = 1227
         Acct-Status-Type = Start
         Acct-Delay-Time = 4
         Caller-ID = "0386249797"
         Client-Port-DNIS = "0198308020"
         Framed-Protocol = PPP
         Framed-Address = 121.79.64.225
         X-Ascend-Billing-Number = "W5"
         User-Service-Type = Framed
         Client-Id = 124.254.72.20
         Acct-Input-Octets = 0
         Acct-Output-Octets = 0
         Acct-Delay-Time = 0
         Acct-Session-Time = 0
         Acct-Session-Id = "301[]426932183"
Wed May 27 09:19:54 2009 : Debug: +- entering group preacct
Wed May 27 09:19:54 2009 : Debug:   modsingle[preacct]: calling preprocess 
(rlm_preprocess) for request 0
Wed May 27 09:19:54 2009 : Debug:       expand: %{User-Name} -> 
sajeewaw@isp1.net.au
Wed May 27 09:19:54 2009 : Debug:   modsingle[preacct]: returned from 
preprocess (rlm_preprocess) for request 0
Wed May 27 09:19:54 2009 : Debug: ++[preprocess] returns ok
Wed May 27 09:19:54 2009 : Debug:   modsingle[preacct]: calling suffix 
(rlm_realm) for request 0
Wed May 27 09:19:54 2009 : Debug:     rlm_realm: Looking up realm 
"isp1.net.au" for User-Name = "sajeewaw@isp1.net.au"
Wed May 27 09:19:54 2009 : Debug:     rlm_realm: Found realm "DEFAULT"
Wed May 27 09:19:54 2009 : Debug:     rlm_realm: Adding Stripped-User-Name 
= "sajeewaw"
Wed May 27 09:19:54 2009 : Debug:     rlm_realm: Adding Realm = "DEFAULT"
Wed May 27 09:19:54 2009 : Debug:     rlm_realm: Accounting realm is 
LOCAL.
Wed May 27 09:19:54 2009 : Debug:   modsingle[preacct]: returned from 
suffix (rlm_realm) for request 0
Wed May 27 09:19:54 2009 : Debug: ++[suffix] returns noop
Wed May 27 09:19:54 2009 : Debug: +- entering group accounting
Wed May 27 09:19:54 2009 : Debug:   modsingle[accounting]: calling 
accounting_1 (rlm_sql) for request 0
Wed May 27 09:19:54 2009 : Debug:       expand: INSERT DELAYED INTO 
RADUSAGE_%Y%m (USERNAME, TIME_STAMP, ACCTSTATUSTYPE, ACCTDELAYTIME, 
ACCTINPUTOCTETS, ACCTOUTPUTOCTETS, ACCTSESSIONID, ACCTSESSIONTIME, 
ACCTTERMINATECAUSE, FRAMEDIPADDRESS, NASIDENTIFIER, NASPORT, DNIS, 
CALLINGSTATIONID, CALLZONE) VALUES 
('%{User-Name}','%T','1','%{Acct-Delay-Time}','%{Acct-Input-Octets}','%{Acct-Output-Octets}','%{Acct-Session-Id}','%{Acct-Session-Time}','%{Ascend-Disconnect-Cause}','%{Framed-IP-Address}','%{NAS-IP-Address}','%{NAS-Port}','%{Called-Station-Id}','%{Calling-Station-Id}','%{X-Ascend-Billing-Number}') 
-> INSERT DELAYED INTO RADUSAGE_200905 (USERNAME, TIME_STAMP, 
ACCTSTATUSTYPE, ACCTDELAYTIME, ACCTINPUTOCTETS, ACCTOUTPUTOCTETS, 
ACCTSESSIONID, ACCTSESSIONTIME, ACCTTERMINATECAUSE, FRAMEDIPADDRESS, 
NASIDENTIFIER, NASPORT, DNIS, CALLINGSTATIONID, CALLZONE) VALUES 
('sajeewaw@isp1.net.au','2009-05-27-09.19.54.000000','1','4','0','0','301=5B=5D426932183','0','','121.79.64.225','124.254.72.20','1227','0198308020','0386249797','W5')
Wed May 27 09:19:54 2009 : Debug: rlm_sql (accounting_1): Reserving sql 
socket id: 4
Wed May 27 09:19:54 2009 : Debug: rlm_sql (accounting_1): Released sql 
socket id: 4
Wed May 27 09:19:54 2009 : Debug:   modsingle[accounting]: returned from 
accounting_1 (rlm_sql) for request 0
Wed May 27 09:19:54 2009 : Debug: ++[accounting_1] returns ok
Wed May 27 09:19:54 2009 : Debug:   modsingle[accounting]: calling 
accounting_2 (rlm_sql) for request 0
Wed May 27 09:19:54 2009 : Debug:       expand: INSERT INTO RADONLINE 
(USERNAME, NASIDENTIFIER, NASPORT, ACCTSESSIONID, TIME_STAMP, 
FRAMEDIPADDRESS, NASPORTTYPE, SERVICETYPE, CALLINGSTATIONID, 
CALLEDSTATIONID, CALLZONE) VALUES ('%{User-Name}', '%{NAS-IP-Address}', 
'%{NAS-Port}', '%{Acct-Session-Id}', '%T', '%{Framed-IP-Address}', 
'0%{NAS-Port-Type}', '%{Service-Type}', '%{Calling-Station-Id}', 
'%{Called-Station-Id}', '%{X-Ascend-Billing-Number}') -> INSERT INTO 
RADONLINE (USERNAME, NASIDENTIFIER, NASPORT, ACCTSESSIONID, TIME_STAMP, 
FRAMEDIPADDRESS, NASPORTTYPE, SERVICETYPE, CALLINGSTATIONID, 
CALLEDSTATIONID, CALLZONE) VALUES ('sajeewaw@isp1.net.au', 
'124.254.72.20', '1227', '301=5B=5D426932183', 
'2009-05-27-09.19.54.000000', '121.79.64.225', '0Async', 'Framed', 
'0386249797', '0198308020', 'W5')
Wed May 27 09:19:54 2009 : Debug: rlm_sql (accounting_2): Reserving sql 
socket id: 4
Wed May 27 09:19:54 2009 : Debug: rlm_sql (accounting_2): Released sql 
socket id: 4
Wed May 27 09:19:54 2009 : Debug:   modsingle[accounting]: returned from 
accounting_2 (rlm_sql) for request 0
Wed May 27 09:19:54 2009 : Debug: ++[accounting_2] returns ok
Wed May 27 09:19:54 2009 : Debug:   modsingle[accounting]: calling prepaid 
(rlm_sql) for request 0
Wed May 27 09:19:54 2009 : Debug:       expand:  ->
Wed May 27 09:19:54 2009 : Debug: rlm_sql (prepaid): Reserving sql socket 
id: 4
Wed May 27 09:19:54 2009 : Debug: rlm_sql (prepaid): Released sql socket 
id: 4
Wed May 27 09:19:54 2009 : Debug:   modsingle[accounting]: returned from 
prepaid (rlm_sql) for request 0
Wed May 27 09:19:54 2009 : Debug: ++[prepaid] returns ok
Sending Accounting-Response of id 1 to 192.168.0.19 port 1778
Wed May 27 09:19:54 2009 : Debug: Finished request 0.
Wed May 27 09:19:54 2009 : Debug: Cleaning up request 0 ID 1 with 
timestamp +6
Wed May 27 09:19:54 2009 : Debug: Going to the next request
Wed May 27 09:19:54 2009 : Debug: Ready to process requests.

Regards,

Sajeewa Warnakulasuriya

Systems Development Manager

ispONE is a wholesale ISP built to help internet access resellers and
independent ISPs to compete in the Australian marketplace through
ONE Brand, ONE Provider, ONE Solution.

Level 14
520 Collins Street
Melbourne 3000 VIC

Phone:  1300 663 400

Fax:      1300 665 400

E-Mail: sajeewaw@ispone.com.au

Web:    http://www.ispone.com.au/