rendered paste body
rad_recv: Access-Request packet from host 127.0.0.1:55749, id=116, length=220
--- Walking the entire request list ---
Waking up in 4 seconds...
Thread 2 got semaphore
Thread 2 handling request 460, (93 handled so far)
User-Name = "O"
NAS-IP-Address = 200.68.67.84
NAS-Identifier = "gk"
NAS-Port-Type = Virtual
Service-Type = Login-User
Framed-IP-Address = 200.68.67.83
Calling-Station-Id = "O"
Called-Station-Id = "59394050407"
h323-conf-id = "h323-conf-id=40F00 2E010212 813A7232 13760B6C"
h323-call-origin = "h323-call-origin=originate"
h323-call-type = "h323-call-type=VoIP"
h323-gw-id = "h323-gw-id=gk"
User-Password = "O"
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 460
modcall[authorize]: module "preprocess" returns ok for request 460
modcall[authorize]: module "digest" returns noop for request 460
*** bs.authorize ***
<class 'controller.Controller'>.authorize
*** h323 ***
*** (('User-Password', 'O'), ('NAS-IP-Address', '200.68.67.84'), ('User-Name', 'O'), ('h323-gw-id', 'gk'), ('h323-call-type', 'VoIP'), ('Framed-IP-Address', '200.68.67.83'), ('Called-Station-Id', '59394050407'), ('Service-Type', 'Login-User'), ('NAS-Identifier', 'gk'), ('Client-IP-Address', '127.0.0.1'), ('h323-conf-id', '40F00 2E010212 813A7232 13760B6C'), ('h323-call-origin', 'originate'), ('NAS-Port-Type', 'Virtual'), ('Calling-Station-Id', 'O')) ***
*** 200.68.67.83 ***
200.68.67.83
<class 'db.user.USER'>.moneyOk
<class 'db.origin.ORIGIN'>.passControls
<class 'db.origin.ORIGIN'>.rewrite
<class 'db.user.USER'>.hierarchy
[<db.user.USER object at 0xb7402fcc>]
<class 'db.user.USER'>.canCall
<class 'db.user.USER'>.priceRule
<class 'db.user.USER'>.route
<class 'db.user.OROUTE'>.originMatches
<class 'db.user.OROUTE'>.destinyMatches
1
<class 'db.destiny.DESTINY'>.canCall
<class 'db.destiny.DESTINY'>.passControls
<class 'db.destiny.DESTINY'>.priceRule
<class 'db.destiny.DESTINY'>.route
*** checking prefix ***
<class 'db.destiny.DROUTE'>.destinyMatches
1
<class 'db.destiny.DESTINY'>.rewrite
rlm_python:authorize: 'User-Password' = 'O'
rlm_python:authorize: 'NAS-IP-Address' = '200.68.67.84'
rlm_python:authorize: 'User-Name' = 'O'
rlm_python:authorize: 'h323-gw-id' = 'gk'
rlm_python:authorize: 'h323-call-type' = 'VoIP'
rlm_python:authorize: 'Framed-IP-Address' = '200.68.67.83'
rlm_python:authorize: 'Called-Station-Id' = '59394050407'
rlm_python:authorize: 'h323-redirect-ip-address' = '200.68.67.82'
rlm_python:authorize: 'Service-Type' = 'Login-User'
rlm_python:authorize: 'NAS-Identifier' = 'gk'
rlm_python:authorize: 'Client-IP-Address' = '127.0.0.1'
rlm_python:authorize: 'h323-conf-id' = '40F00 2E010212 813A7232 13760B6C'
rlm_python:authorize: 'h323-call-origin' = 'originate'
rlm_python:authorize: 'h323-redirect-number' = '00559394050407'
rlm_python:authorize: 'NAS-Port-Type' = 'Virtual'
rlm_python:authorize: 'Calling-Station-Id' = 'O'
rlm_python:authorize: 'Session-Timeout' = '7200'
rlm_python:authorize: 'Auth-Type' = 'Accept'
modcall[authorize]: module "python" returns updated for request 460
modcall: leaving group authorize (returns updated) for request 460
rad_check_password: Found Auth-Type Accept
rad_check_password: Auth-Type = Accept, accepting the user
Sending Access-Accept of id 116 to 127.0.0.1 port 55749
User-Password = "O"
NAS-IP-Address = 200.68.67.84
User-Name = "O"
h323-gw-id = "gk"
h323-call-type = "VoIP"
Framed-IP-Address = 200.68.67.83
Called-Station-Id = "59394050407"
h323-redirect-ip-address = "200.68.67.82"
Service-Type = Login-User
NAS-Identifier = "gk"
h323-conf-id = "40F00 2E010212 813A7232 13760B6C"
h323-call-origin = "originate"
h323-redirect-number = "00559394050407"
NAS-Port-Type = Virtual
Calling-Station-Id = "O"
Session-Timeout = 7200
rad_recv: Accounting-Request packet from host 127.0.0.1:22510, id=165, length=393
Waking up in 4 seconds...
Thread 1 got semaphore
Threads: total/active/spare threads = 5/1/4
Thread 1 handling request 461, (95 handled so far)
Acct-Status-Type = Start
NAS-IP-Address = 200.68.67.84
NAS-Identifier = "gk"
NAS-Port-Type = Virtual
Service-Type = Login-User
Acct-Session-Id = "471fc1d800000024"
User-Name = "O"
Framed-IP-Address = 200.68.67.83
Calling-Station-Id = "O"
Called-Station-Id = "00559394050407"
h323-conf-id = "h323-conf-id=40F00 2E010212 813A7232 13760B6C"
h323-gw-id = "h323-gw-id=gk"
h323-call-origin = "h323-call-origin=proxy"
h323-call-type = "h323-call-type=VoIP"
h323-setup-time = "h323-setup-time=19:58:31.000 ART Wed Oct 24 2007"
h323-remote-address = "h323-remote-address=200.68.67.82"
Cisco-AVPair = "h323-ivr-out=h323-call-id:40F00 2E010212 813A7232 13760B6B"
Acct-Delay-Time = 0
Processing the preacct section of radiusd.conf
modcall: entering group preacct for request 461
modcall[preacct]: module "preprocess" returns noop for request 461
rlm_acct_unique: WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent
rlm_acct_unique: Hashing ',Client-IP-Address = 127.0.0.1,NAS-IP-Address = 200.68.67.84,Acct-Session-Id = "471fc1d800000024",User-Name = "O"'
rlm_acct_unique: Acct-Unique-Session-ID = "67ac2a4f0c10fbe9".
modcall[preacct]: module "acct_unique" returns ok for request 461
rlm_realm: No '@' in User-Name = "O", looking up realm NULL
rlm_realm: No such realm "NULL"
modcall[preacct]: module "suffix" returns noop for request 461
Finished request 460
modcall[preacct]: module "python" returns ok for request 461
modcall: leaving group preacct (returns ok) for request 461
Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 461
Going to the next request
radius_xlat: '/usr/local/stow/freeradius-1.1.7/var/log/radius/radacct/127.0.0.1/detail-20071024'
rlm_detail: /usr/local/stow/freeradius-1.1.7/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /usr/local/stow/freeradius-1.1.7/var/log/radius/radacct/127.0.0.1/detail-20071024
Thread 2 waiting to be assigned a request
modcall[accounting]: module "detail" returns ok for request 461
*** bs.accounting ***
*** isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart isStart ***
<class 'controller.Controller'>.start
Traceback (most recent call last):
File "/usr/local/share/bs/bs.py", line 81, in accounting
cntrl.start(request)
File "/usr/local/share/bs/controller.py", line 71, in start
cdr = db.cdr.makeCdr(u, request)
File "/usr/local/share/bs/db/cdr.py", line 144, in makeCdr
if isStart(request): c = StartCdr(user, request)
File "build/bdist.linux-i686/egg/sqlalchemy/orm/attributes.py", line 1016, in init
File "/usr/local/share/bs/db/cdr.py", line 80, in __init__
self.user_time = msg.userTime
File "/usr/local/share/bs/message.py", line 36, in __getattr__
assert _map.has_key(attr), attr
AssertionError: userTime
modcall[accounting]: module "python" returns ok for request 461
modcall: leaving group accounting (returns ok) for request 461
Sending Accounting-Response of id 165 to 127.0.0.1 port 22510
Finished request 461
Going to the next request
Thread 1 waiting to be assigned a request
--- Walking the entire request list ---
Server rejecting request 460.
Server rejecting request 461.
Waking up in 5 seconds...
Threads: total/active/spare threads = 5/0/5
rad_recv: Accounting-Request packet from host 127.0.0.1:22510, id=166, length=492
--- Walking the entire request list ---
Re-sending Access-Reject of id 116 to 127.0.0.1 port 55749
Cleaning up request 460 ID 116 with timestamp 471fce17
Re-sending Accounting-Response of id 165 to 127.0.0.1 port 22510
Cleaning up request 461 ID 165 with timestamp 471fce17
Waking up in 4 seconds...
Thread 4 got semaphore
Thread 4 handling request 462, (93 handled so far)
Acct-Status-Type = Stop
NAS-IP-Address = 200.68.67.84
NAS-Identifier = "gk"
NAS-Port-Type = Virtual
Service-Type = Login-User
Acct-Session-Id = "471fc1d800000024"
User-Name = "O"
Framed-IP-Address = 200.68.67.83
Acct-Session-Time = 0
Calling-Station-Id = "O"
Called-Station-Id = "00559394050407"
h323-conf-id = "h323-conf-id=40F00 2E010212 813A7232 13760B6C"
h323-gw-id = "h323-gw-id=gk"
h323-call-origin = "h323-call-origin=proxy"
h323-call-type = "h323-call-type=VoIP"
h323-setup-time = "h323-setup-time=19:58:31.000 ART Wed Oct 24 2007"
h323-disconnect-time = "h323-disconnect-time=19:58:39.000 ART Wed Oct 24 2007"
h323-disconnect-cause = "h323-disconnect-cause=10"
h323-remote-address = "h323-remote-address=200.68.67.82"
Cisco-AVPair = "h323-ivr-out=h323-call-id:40F00 2E010212 813A7232 13760B6B"
Acct-Delay-Time = 0
Processing the preacct section of radiusd.conf
modcall: entering group preacct for request 462
modcall[preacct]: module "preprocess" returns noop for request 462
rlm_acct_unique: WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent
rlm_acct_unique: Hashing ',Client-IP-Address = 127.0.0.1,NAS-IP-Address = 200.68.67.84,Acct-Session-Id = "471fc1d800000024",User-Name = "O"'
rlm_acct_unique: Acct-Unique-Session-ID = "67ac2a4f0c10fbe9".
modcall[preacct]: module "acct_unique" returns ok for request 462
rlm_realm: No '@' in User-Name = "O", looking up realm NULL
rlm_realm: No such realm "NULL"
modcall[preacct]: module "suffix" returns noop for request 462
modcall[preacct]: module "python" returns ok for request 462
modcall: leaving group preacct (returns ok) for request 462
Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 462
radius_xlat: '/usr/local/stow/freeradius-1.1.7/var/log/radius/radacct/127.0.0.1/detail-20071024'
rlm_detail: /usr/local/stow/freeradius-1.1.7/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /usr/local/stow/freeradius-1.1.7/var/log/radius/radacct/127.0.0.1/detail-20071024
modcall[accounting]: module "detail" returns ok for request 462
*** bs.accounting ***
*** cdr.isConnect:request.acctStatusType=Stop:request.acctSessionTime=0:request.connectTime=None ***
*** isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop isStop ***
<class 'controller.Controller'>.stop
*** h323-call-id:40F00 2E010212 813A7232 13760B6B ***
*** cdr.isConnect:request.acctStatusType=Stop:request.acctSessionTime=0:request.connectTime=None ***
Traceback (most recent call last):
File "/usr/local/share/bs/bs.py", line 93, in accounting
cntrl.stop(request)
File "/usr/local/share/bs/controller.py", line 253, in stop
cdr = db.cdr.makeCdr(u, request)
File "/usr/local/share/bs/db/cdr.py", line 147, in makeCdr
elif isStop(request): c = StopCdr(user, request)
File "build/bdist.linux-i686/egg/sqlalchemy/orm/attributes.py", line 1016, in init
File "/usr/local/share/bs/db/cdr.py", line 106, in __init__
StartCdr.__init__(self, user, msg)
File "build/bdist.linux-i686/egg/sqlalchemy/orm/attributes.py", line 1016, in init
File "/usr/local/share/bs/db/cdr.py", line 80, in __init__
self.user_time = msg.userTime
File "/usr/local/share/bs/message.py", line 36, in __getattr__
assert _map.has_key(attr), attr
AssertionError: userTime
modcall[accounting]: module "python" returns ok for request 462
modcall: leaving group accounting (returns ok) for request 462
Sending Accounting-Response of id 166 to 127.0.0.1 port 22510
Finished request 462
Going to the next request
Thread 4 waiting to be assigned a request
--- Walking the entire request list ---
Server rejecting request 462.
Waking up in 5 seconds...