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...