Current-time: Jan 29 11:53:17 PST (UTC -0800) H323-conf-id: 348E9091 16046E71 2DA23176 43B5D459 SIP Call-ID: 94.23.242.200-1264794731.128 SIP Call-ID: 4fc471775509d8b61aeb822b7fdba594@94.23.225.212 Requests: 6 REQUEST-- Jan 29 11:52:12: Processing request (BE ver1.245.2.11,pid15598): NAS-IP-Address = '94.23.242.200' NAS-Port-Name = 'SIP/41215500329-08839950' User-Name = '41215500329' Called-Station-Id = '0216912818' Calling-Station-Id = '41215500329' h323-conf-id = '348E9091 16046E71 2DA23176 43B5D459' call-id = '94.23.242.200-1264794731.128' Digest-Attributes = 'User-Name = "41215500329"' Digest-Attributes = 'Realm = "switzernet"' Digest-Attributes = 'Nonce = "115337a4"' Digest-Attributes = 'URI = "sip:0216912818@94.23.242.200"' Digest-Attributes = 'Method = "INVITE"' Digest-Attributes = 'Algorithm = "MD5"' Digest-Response = 'f52fcb000657b846082f0f5362895fe6' h323-ivr-out = 'PortaBilling_Routing:SIP' Jan 29 11:52:12: h323-conf-id=348E9091 16046E71 2DA23176 43B5D459/1, call-id=94.23.242.200-1264794731.128/1 Jan 29 11:52:12: H323/SIP call, use h323-conf-id, but remember call-id Jan 29 11:52:12: Checking if this call comes through a VoIP from vendor connection Jan 29 11:52:12: No VoIP from vendor connections were found Jan 29 11:52:12: PrepareNexecute 'AccountAuth' Jan 29 11:52:12: SQL query 'AccountAuth' executed in 0.001887 seconds Jan 29 11:52:12: Found Account: 41215500329[58048,credit,balance=0.28000,limit=none] of customer Swiss offices[16165,balance=633.56000,limit=700.00000] Jan 29 11:52:12: PrepareNexecute 'GetSessions' Jan 29 11:52:12: SQL query 'GetSessions' executed in 0.000971 seconds Jan 29 11:52:12: Account 41215500329 is already logged in, other session with call ID=2129AF17 60390377 2722CBBF 613CEA4D Jan 29 11:52:12: Verification of password using method 'digest_response': success Jan 29 11:52:12: Applying customer dialing translation rule on CLD ... Jan 29 11:52:12: Translation 'local_to_e164($_,{cc=>'41',dp=>'0',ip=>'00'});#% cc=41 dp=0 ip=00' applied: '0216912818' -> '41216912818' Jan 29 11:52:12: PrepareNexecute 'AccountAuth' Jan 29 11:52:12: SQL query 'AccountAuth' executed in 0.001392 seconds Jan 29 11:52:12: CLD '41216912818' is an off-net number Jan 29 11:52:12: Setting up a new charge with tariff 'business' ... Jan 29 11:52:12: Using peak rate, since no off-peak is defined Jan 29 11:52:12: PrepareNexecute 'GetPricePerDestination*' Jan 29 11:52:12: SQL query 'GetPricePerDestination*' executed in 0.001728 seconds Jan 29 11:52:12: Compute maximum call duration for leg Account 41215500329 to destination with funds 66.44 (customer funds 66.4400000000001 reduced to 66.44) Jan 29 11:52:12: Maximum call duration: 199320 announced as 199320 (+1x1x0.02+199319x1x0.02) by rate 2487323 using 98193 as seed Jan 29 11:52:12: Remote termination 'PortaSIP': Calculating routing for 41216912818 Jan 29 11:52:12: RTP Proxy with origination preference 'Undetermined', Calling party NOT behind NAT. Jan 29 11:52:12: Looking up routes to '41216912818' using '' routing plan Jan 29 11:52:12: PrepareNexecute 'GetRoutingPerDestination*' Jan 29 11:52:12: SQL query 'GetRoutingPerDestination*' executed in 0.005836 seconds Jan 29 11:52:12: Checked 2010-01-29 20:52:12 Europe/Zurich against 'hr{17-7} wd{mo-fr }, wd{sa su }, md{25} mo{dec}, md{26} mo{dec}, md{1} mo{jan}, md{2} mo{jan}, md{10} mo{apr}, md{13} mo{apr}, md{1} mo{may}, md{1} mo{jun}, md{1} mo{aug}': 1 Jan 29 11:52:12: Start of call is peak level 1 Jan 29 11:52:12: Using peak rate, since no off-peak is defined Jan 29 11:52:12: Checked 2010-01-29 20:52:12 Europe/Zurich against 'hr{17-7} wd{mo-fr }, wd{sa su }, md{25} mo{dec}, md{26} mo{dec}, md{1} mo{jan}, md{2} mo{jan}, md{10} mo{apr}, md{13} mo{apr}, md{1} mo{may}, md{1} mo{jun}, md{1} mo{aug}': 1 Jan 29 11:52:12: Start of call is peak level 1 Jan 29 11:52:12: Checked 2010-01-29 20:52:12 Europe/Zurich against 'hr{17-7} wd{mo-fr }, wd{sa su }, md{25} mo{dec}, md{26} mo{dec}, md{1} mo{jan}, md{2} mo{jan}, md{10} mo{apr}, md{13} mo{apr}, md{1} mo{may}, md{1} mo{jun}, md{1} mo{aug}': 1 Jan 29 11:52:12: Start of call is peak level 1 Jan 29 11:52:12: Using peak rate, since no off-peak is defined Jan 29 11:52:12: Using peak rate, since no off-peak is defined Jan 29 11:52:12: Using peak rate, since no off-peak is defined Jan 29 11:52:12: Checked 2010-01-29 20:52:12 Europe/Zurich against 'hr{17-7} wd{mo-fr }, wd{sa su }, md{25} mo{dec}, md{26} mo{dec}, md{1} mo{jan}, md{2} mo{jan}, md{10} mo{apr}, md{13} mo{apr}, md{1} mo{may}, md{1} mo{jun}, md{1} mo{aug}': 1 Jan 29 11:52:12: Start of call is peak level 1 Jan 29 11:52:12: Using peak rate, since no off-peak is defined Jan 29 11:52:12: Applying route outgoing CLD translation on '41216912818' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/;' applied: '41216912818' -> '+41216912818' Jan 29 11:52:12: Applying route outgoing CLD translation on '41216912818' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/;' applied: '41216912818' -> '+41216912818' Jan 29 11:52:12: Applying route outgoing CLD translation on '41216912818' ... Jan 29 11:52:12: Translation 's/^(\d)/00$1/;' applied: '41216912818' -> '0041216912818' Jan 29 11:52:12: Applying route outgoing CLD translation on '41216912818' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/' applied: '41216912818' -> '+41216912818' Jan 29 11:52:12: Applying route outgoing CLI translation on '41215500329' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 11:52:12: Applying route outgoing CLI translation on '41215500329' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 11:52:12: Applying route outgoing CLI translation on '41215500329' ... Jan 29 11:52:12: Translation 's/^(\d)/00$1/;' applied: '41215500329' -> '0041215500329' Jan 29 11:52:12: Applying route outgoing CLI translation on '41215500329' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 11:52:12: Result routes to destination '41216912818': +41216912818@212.249.15.9, prio = 10, cost = 0.00654, off-peak, 'OpenSER 9' - to remote GW +41216912818@212.249.15.3, prio = 10, cost = 0.00654, off-peak, 'OpenSER 3' - to remote GW 0041216912818@217.168.45.4, prio = 9, cost = 0.00000, off-peak, 'Asterisk SS7' - to remote GW +41216912818@87.106.213.52, prio = 8, cost = 0.00000, 'OpenSER UK' - to remote GW Jan 29 11:52:12: Enhance lifetime with 1800s to Fri Jan 29 12:22:12 2010 Jan 29 11:52:12: Authentication acknowledge response h323-ivr-in = PortaBilling_Routing:@;g-hunt=seq h323-ivr-in = PortaBilling_Routing: @;g-hunt=skip;expires=300;credit-time=199320;cli=+41215500329;patience=20 h323-ivr-in = PortaBilling_Routing: +41216912818@212.249.15.9 h323-ivr-in = PortaBilling_Routing: +41216912818@212.249.15.3 h323-ivr-in = PortaBilling_Routing: 0041216912818@217.168.45.4;cli=0041215500329;rtpp=1 h323-ivr-in = PortaBilling_Routing: +41216912818@87.106.213.52 h323-billing-model = 0 h323-ivr-in = Tariff:business h323-ivr-in = PortaBilling_CLI:41215500329 h323-ivr-in = MOH:1 h323-ivr-in = PortaBilling_CompleteNumber:41216912818 h323-ivr-in = PortaBilling_Auth_CLD:41216912818 h323-ivr-in = PortaBilling_Auth_Reseller_CLD:41216912818 h323-ivr-in = DURATION:199320 h323-return-code = 0 h323-currency = CHF h323-credit-time = 199320 h323-preferred-lang = en Jan 29 11:52:12: ...Done Authorize/INVITE in 0.039810 seconds, 0.011814 spent in SQL queries. --REQUEST REQUEST-- Jan 29 11:52:12: Processing request (BE ver1.245.2.11,pid15598): NAS-IP-Address = '91.121.19.149' User-Name = '94.23.225.212' Called-Station-Id = '41216912818' Calling-Station-Id = '41215500329' h323-conf-id = '348E9091 16046E71 2DA23176 43B5D459' call-id = '4fc471775509d8b61aeb822b7fdba594@94.23.225.212' Password = 'xxxxxxxx' h323-remote-address = '94.23.225.212' h323-session-protocol = 'sipv2' h323-ivr-out = 'PortaBilling_Routing:SIP' h323-ivr-out = 'PortaBilling_AuthMethod:INVITE' h323-ivr-out = 'PortaBilling_Notify:rtpp_level=3' h323-ivr-out = 'PortaBilling_Seed:3714566036' NAS-Port = '5060' Jan 29 11:52:12: h323-conf-id=348E9091 16046E71 2DA23176 43B5D459/1, call-id=4fc471775509d8b61aeb822b7fdba594@94.23.225.212/1 Jan 29 11:52:12: Found a call in cache with such id Jan 29 11:52:12: Authorization of the trusted node Jan 29 11:52:12: IP based authorization, force 'plaintext' password verification Jan 29 11:52:12: Verification of password using method 'plaintext': success Jan 29 11:52:12: '94.23.225.212' is a trusted node's ID or IP, unable to use it as an account ID. Correct account ID should be available on the other call legs Jan 29 11:52:12: PrepareNexecute 'AccountAuth' Jan 29 11:52:12: SQL query 'AccountAuth' executed in 0.001513 seconds Jan 29 11:52:12: CLD '41216912818' is an off-net number Jan 29 11:52:12: Remote termination 'PortaSIP': Calculating routing for 41216912818 Jan 29 11:52:12: Routing information retrieved from previous auth request Jan 29 11:52:12: RTP Proxy with origination preference '', Calling party NOT behind NAT. Jan 29 11:52:12: Looking up routes to '41216912818' using '' routing plan Jan 29 11:52:12: PrepareNexecute 'GetRoutingPerDestination*' Jan 29 11:52:12: SQL query 'GetRoutingPerDestination*' executed in 0.034631 seconds Jan 29 11:52:12: Checked 2010-01-29 20:52:12 Europe/Zurich against 'hr{17-7} wd{mo-fr }, wd{sa su }, md{25} mo{dec}, md{26} mo{dec}, md{1} mo{jan}, md{2} mo{jan}, md{10} mo{apr}, md{13} mo{apr}, md{1} mo{may}, md{1} mo{jun}, md{1} mo{aug}': 1 Jan 29 11:52:12: Start of call is peak level 1 Jan 29 11:52:12: Using peak rate, since no off-peak is defined Jan 29 11:52:12: Checked 2010-01-29 20:52:12 Europe/Zurich against 'hr{17-7} wd{mo-fr }, wd{sa su }, md{25} mo{dec}, md{26} mo{dec}, md{1} mo{jan}, md{2} mo{jan}, md{10} mo{apr}, md{13} mo{apr}, md{1} mo{may}, md{1} mo{jun}, md{1} mo{aug}': 1 Jan 29 11:52:12: Start of call is peak level 1 Jan 29 11:52:12: Checked 2010-01-29 20:52:12 Europe/Zurich against 'hr{17-7} wd{mo-fr }, wd{sa su }, md{25} mo{dec}, md{26} mo{dec}, md{1} mo{jan}, md{2} mo{jan}, md{10} mo{apr}, md{13} mo{apr}, md{1} mo{may}, md{1} mo{jun}, md{1} mo{aug}': 1 Jan 29 11:52:12: Start of call is peak level 1 Jan 29 11:52:12: Using peak rate, since no off-peak is defined Jan 29 11:52:12: Using peak rate, since no off-peak is defined Jan 29 11:52:12: Using peak rate, since no off-peak is defined Jan 29 11:52:12: Checked 2010-01-29 20:52:12 Europe/Zurich against 'hr{17-7} wd{mo-fr }, wd{sa su }, md{25} mo{dec}, md{26} mo{dec}, md{1} mo{jan}, md{2} mo{jan}, md{10} mo{apr}, md{13} mo{apr}, md{1} mo{may}, md{1} mo{jun}, md{1} mo{aug}': 1 Jan 29 11:52:12: Start of call is peak level 1 Jan 29 11:52:12: Using peak rate, since no off-peak is defined Jan 29 11:52:12: Applying route outgoing CLD translation on '41216912818' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/;' applied: '41216912818' -> '+41216912818' Jan 29 11:52:12: Applying route outgoing CLD translation on '41216912818' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/;' applied: '41216912818' -> '+41216912818' Jan 29 11:52:12: Applying route outgoing CLD translation on '41216912818' ... Jan 29 11:52:12: Translation 's/^(\d)/00$1/;' applied: '41216912818' -> '0041216912818' Jan 29 11:52:12: Applying route outgoing CLD translation on '41216912818' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/' applied: '41216912818' -> '+41216912818' Jan 29 11:52:12: Applying route outgoing CLI translation on '41215500329' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 11:52:12: Applying route outgoing CLI translation on '41215500329' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 11:52:12: Applying route outgoing CLI translation on '41215500329' ... Jan 29 11:52:12: Translation 's/^(\d)/00$1/;' applied: '41215500329' -> '0041215500329' Jan 29 11:52:12: Applying route outgoing CLI translation on '41215500329' ... Jan 29 11:52:12: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 11:52:12: Result routes to destination '41216912818': +41216912818@212.249.15.9, prio = 10, cost = 0.00654, off-peak, 'OpenSER 9' - to remote GW +41216912818@212.249.15.3, prio = 10, cost = 0.00654, off-peak, 'OpenSER 3' - to remote GW 0041216912818@217.168.45.4, prio = 9, cost = 0.00000, off-peak, 'Asterisk SS7' - to remote GW +41216912818@87.106.213.52, prio = 8, cost = 0.00000, 'OpenSER UK' - to remote GW Jan 29 11:52:12: Authentication acknowledge response h323-ivr-in = PortaBilling_Routing:@;g-hunt=seq h323-ivr-in = PortaBilling_Routing: @;g-hunt=skip;expires=300;credit-time=-1;cli=+41215500329;patience=20 h323-ivr-in = PortaBilling_Routing: +41216912818@212.249.15.9 h323-ivr-in = PortaBilling_Routing: +41216912818@212.249.15.3 h323-ivr-in = PortaBilling_Routing: 0041216912818@217.168.45.4;cli=0041215500329;rtpp=1 h323-ivr-in = PortaBilling_Routing: +41216912818@87.106.213.52 h323-ivr-in = PortaBilling_CacheExpiration:Never h323-ivr-in = PortaBilling_CLI:41215500329 h323-ivr-in = PortaBilling_CompleteNumber:41216912818 h323-ivr-in = PortaBilling_Auth_CLD:41216912818 h323-ivr-in = PortaBilling_Auth_Reseller_CLD:41216912818 h323-return-code = 13 Jan 29 11:52:12: ...Done Authorize/INVITE in 0.056242 seconds, 0.036144 spent in SQL queries. --REQUEST REQUEST-- Jan 29 11:52:22: Processing request (BE ver1.245.2.11,pid15598): NAS-IP-Address = '91.121.19.149' User-Name = '94.23.225.212' Called-Station-Id = '+41216912818' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Start' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '19:52:13.031 GMT Fri Jan 29 2010' h323-connect-time = '19:52:22.204 GMT Fri Jan 29 2010' h323-conf-id = '348E9091 16046E71 2DA23176 43B5D459' call-id = '4fc471775509d8b61aeb822b7fdba594@94.23.225.212' Acct-Session-Id = '4fc471775509d8b61aeb822b7fdba594@94.23.225.212' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' h323-remote-address = '212.249.15.9' h323-ivr-out = 'DURATION:7200' h323-ivr-out = 'PortaBilling_Auth_CLD:41216912818' h323-ivr-out = 'PortaBilling_Seed:3714566036' alert-timepoint = '19:52:14.282 GMT Fri Jan 29 2010' NAS-Port = '5060' Exec-Program-Log = 'porta-billing.pl' Jan 29 11:52:22: h323-conf-id=348E9091 16046E71 2DA23176 43B5D459/1, call-id=4fc471775509d8b61aeb822b7fdba594@94.23.225.212/1 Jan 29 11:52:22: Found a call in cache with such id Jan 29 11:52:22: Copying randomization seed '3714566036' into request's PortaBilling_Seed attribute Jan 29 11:52:22: Copying originator authorized CLD '41216912818' into current request Jan 29 11:52:22: Copying reseller authorized CLD '41216912818' into current request Jan 29 11:52:22: Replacing username '94.23.225.212' with the real username '41215500329' Jan 29 11:52:22: Copied account: 41215500329[58048,credit,balance=0.28000,limit=none] of customer Swiss offices[16165,balance=633.56000,limit=700.00000] from '94.23.242.200' into the current request Jan 29 11:52:22: Fixing time with duration 0 seconds from connect time Jan 29 11:52:22: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 11:52:22: SQL query 'GetActiveLegIdByAcct' executed in 0.002042 seconds Jan 29 11:52:22: Looking up vendor/connection Jan 29 11:52:22: Trying to match connection for call Jan 29 11:52:22: Looking for a connection VoIP/originate Jan 29 11:52:22: Outgoing VoIP, matching by the remote IP address '212.249.15.9' (env 1) Jan 29 11:52:22: Found connection 217 'OpenSER 9' to vendor 'Verizon' Jan 29 11:52:22: Found vendor/connection Jan 29 11:52:22: PrepareNexecute 'InsertActiveLeg' Jan 29 11:52:22: SQL query 'InsertActiveLeg' executed in 0.001956 seconds Jan 29 11:52:22: Accounting response Jan 29 11:52:22: ...Done Accounting/Start/originate/VoIP in 0.011398 seconds, 0.003998 spent in SQL queries. --REQUEST REQUEST-- Jan 29 11:52:22: Processing request (BE ver1.245.2.11,pid15598): NAS-IP-Address = '91.121.19.149' User-Name = '94.23.225.212' Called-Station-Id = '41216912818' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Start' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '19:52:12.927 GMT Fri Jan 29 2010' h323-connect-time = '19:52:22.206 GMT Fri Jan 29 2010' h323-conf-id = '348E9091 16046E71 2DA23176 43B5D459' call-id = '4fc471775509d8b61aeb822b7fdba594@94.23.225.212' Acct-Session-Id = '4fc471775509d8b61aeb822b7fdba594@94.23.225.212' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' h323-remote-address = '94.23.225.212' h323-ivr-out = 'PortaBilling_Seed:3714566036' alert-timepoint = '19:52:22.206 GMT Fri Jan 29 2010' NAS-Port = '5060' Exec-Program-Log = 'porta-billing.pl' Jan 29 11:52:22: h323-conf-id=348E9091 16046E71 2DA23176 43B5D459/1, call-id=4fc471775509d8b61aeb822b7fdba594@94.23.225.212/1 Jan 29 11:52:22: Found a call in cache with such id Jan 29 11:52:22: Copying randomization seed '3714566036' into request's PortaBilling_Seed attribute Jan 29 11:52:22: Copying originator authorized CLD '41216912818' into current request Jan 29 11:52:22: Copying reseller authorized CLD '41216912818' into current request Jan 29 11:52:22: Replacing username '94.23.225.212' with the real username '41215500329' Jan 29 11:52:22: Copied account: 41215500329[58048,credit,balance=0.28000,limit=none] of customer Swiss offices[16165,balance=633.56000,limit=700.00000] from '94.23.242.200' into the current request Jan 29 11:52:22: Fixing time with duration 0 seconds from connect time Jan 29 11:52:22: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 11:52:22: SQL query 'GetActiveLegIdByAcct' executed in 0.001442 seconds Jan 29 11:52:22: Looking up vendor/connection Jan 29 11:52:22: Trying to match connection for call Jan 29 11:52:22: Looking for a connection VoIP/answer Jan 29 11:52:22: VoIP, matching by the node IP '91.121.19.149' and User-Name '94.23.225.212' Jan 29 11:52:22: No VoIP from vendor connections were found Jan 29 11:52:22: Connection to vendor not found Jan 29 11:52:22: PrepareNexecute 'InsertActiveLeg' Jan 29 11:52:22: SQL query 'InsertActiveLeg' executed in 0.00141 seconds Jan 29 11:52:22: Accounting response Jan 29 11:52:22: ...Done Accounting/Start/answer/VoIP in 0.009624 seconds, 0.002852 spent in SQL queries. --REQUEST REQUEST-- Jan 29 11:52:42: Processing request (BE ver1.245.2.11,pid15598): NAS-IP-Address = '91.121.19.149' User-Name = '94.23.225.212' Called-Station-Id = '41216912818' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Stop' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '19:52:12.927 GMT Fri Jan 29 2010' h323-connect-time = '19:52:21.927 GMT Fri Jan 29 2010' h323-disconnect-time = '19:52:40.927 GMT Fri Jan 29 2010' h323-disconnect-cause = '0' h323-voice-quality = '0' h323-conf-id = '348E9091 16046E71 2DA23176 43B5D459' call-id = '4fc471775509d8b61aeb822b7fdba594@94.23.225.212' Acct-Session-Id = '4fc471775509d8b61aeb822b7fdba594@94.23.225.212' Acct-Session-Time = '19' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' h323-remote-address = '94.23.225.212' h323-ivr-out = 'PortaBilling_Seed:3714566036' Acct-Terminate-Cause = 'User-Request' h323-ivr-out = 'PortaBilling_Session:unlock' alert-timepoint = '19:52:22.206 GMT Fri Jan 29 2010' NAS-Port = '5060' Exec-Program-Log = 'porta-billing.pl' Jan 29 11:52:42: h323-conf-id=348E9091 16046E71 2DA23176 43B5D459/1, call-id=4fc471775509d8b61aeb822b7fdba594@94.23.225.212/1 Jan 29 11:52:42: Found a call in cache with such id Jan 29 11:52:42: Copying randomization seed '3714566036' into request's PortaBilling_Seed attribute Jan 29 11:52:42: Copying originator authorized CLD '41216912818' into current request Jan 29 11:52:42: Copying reseller authorized CLD '41216912818' into current request Jan 29 11:52:42: Replacing username '94.23.225.212' with the real username '41215500329' Jan 29 11:52:42: Copied account: 41215500329[58048,credit,balance=0.28000,limit=none] of customer Swiss offices[16165,balance=633.56000,limit=700.00000] from '94.23.242.200' into the current request Jan 29 11:52:42: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 11:52:42: SQL query 'GetActiveLegIdByAcct' executed in 0.001776 seconds Jan 29 11:52:42: PrepareNexecute 'DeleteActiveLeg' Jan 29 11:52:42: SQL query 'DeleteActiveLeg' executed in 0.001341 seconds Jan 29 11:52:42: Force unlock requested by NAS Jan 29 11:52:42: There have been authentication requests from more than one NAS Jan 29 11:52:42: No logged in accounts, call lifetime reduced to 15 Jan 29 11:52:42: Set lifetime with 15s to Fri Jan 29 11:52:57 2010 Jan 29 11:52:42: Looking up vendor/connection Jan 29 11:52:42: Trying to match connection for call Jan 29 11:52:42: Looking for a connection VoIP/answer Jan 29 11:52:42: VoIP, matching by the node IP '91.121.19.149' and User-Name '94.23.225.212' Jan 29 11:52:42: No VoIP from vendor connections were found Jan 29 11:52:42: Connection to vendor not found Jan 29 11:52:42: No connection from vendor Jan 29 11:52:42: Accounting response Jan 29 11:52:42: ...Done Accounting/Stop/answer/VoIP in 0.010800 seconds, 0.003117 spent in SQL queries. --REQUEST REQUEST-- Jan 29 11:52:42: Processing request (BE ver1.245.2.11,pid15598): NAS-IP-Address = '91.121.19.149' User-Name = '94.23.225.212' Called-Station-Id = '+41216912818' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Stop' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '19:52:13.031 GMT Fri Jan 29 2010' h323-connect-time = '19:52:22.031 GMT Fri Jan 29 2010' h323-disconnect-time = '19:52:41.031 GMT Fri Jan 29 2010' h323-disconnect-cause = '0' h323-voice-quality = '0' h323-conf-id = '348E9091 16046E71 2DA23176 43B5D459' call-id = '4fc471775509d8b61aeb822b7fdba594@94.23.225.212' Acct-Session-Id = '4fc471775509d8b61aeb822b7fdba594@94.23.225.212' Acct-Session-Time = '19' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' h323-remote-address = '212.249.15.9' h323-ivr-out = 'DURATION:7200' h323-ivr-out = 'PortaBilling_Auth_CLD:41216912818' h323-ivr-out = 'PortaBilling_Seed:3714566036' Acct-Terminate-Cause = 'User-Request' alert-timepoint = '19:52:14.282 GMT Fri Jan 29 2010' NAS-Port = '5060' Exec-Program-Log = 'porta-billing.pl' Jan 29 11:52:42: h323-conf-id=348E9091 16046E71 2DA23176 43B5D459/1, call-id=4fc471775509d8b61aeb822b7fdba594@94.23.225.212/1 Jan 29 11:52:42: Found a call in cache with such id Jan 29 11:52:42: Copying randomization seed '3714566036' into request's PortaBilling_Seed attribute Jan 29 11:52:42: Copying originator authorized CLD '41216912818' into current request Jan 29 11:52:42: Copying reseller authorized CLD '41216912818' into current request Jan 29 11:52:42: Replacing username '94.23.225.212' with the real username '41215500329' Jan 29 11:52:42: Copied account: 41215500329[58048,credit,balance=0.28000,limit=none] of customer Swiss offices[16165,balance=633.56000,limit=700.00000] from '94.23.242.200' into the current request Jan 29 11:52:42: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 11:52:42: SQL query 'GetActiveLegIdByAcct' executed in 0.001415 seconds Jan 29 11:52:42: PrepareNexecute 'DeleteActiveLeg' Jan 29 11:52:42: SQL query 'DeleteActiveLeg' executed in 0.001516 seconds Jan 29 11:52:42: End of the outgoing call for account, which appears as never logged-in Jan 29 11:52:42: Set lifetime with 15s to Fri Jan 29 11:52:57 2010 Jan 29 11:52:42: Looking up vendor/connection Jan 29 11:52:42: Trying to match connection for call Jan 29 11:52:42: Looking for a connection VoIP/originate Jan 29 11:52:42: Outgoing VoIP, matching by the remote IP address '212.249.15.9' (env 1) Jan 29 11:52:42: Found connection 217 'OpenSER 9' to vendor 'Verizon' Jan 29 11:52:42: Found vendor/connection Jan 29 11:52:42: Applying connection translation rule on CLD ... Jan 29 11:52:42: Translation 's/^\+//;' applied: '+41216912818' -> '41216912818' Jan 29 11:52:42: Charging call ... Jan 29 11:52:42: Initialize new charge clone with tariff 'business' as this one is already initialized with incompatible parameters Jan 29 11:52:42: Setting up a new charge with tariff 'business' ... Jan 29 11:52:42: Using peak rate, since no off-peak is defined Jan 29 11:52:42: PrepareNexecute 'GetPricePerDestination*' Jan 29 11:52:42: SQL query 'GetPricePerDestination*' executed in 0.001767 seconds Jan 29 11:52:42: Calculating account's charge by tariff 'business' Jan 29 11:52:42: Call to '41216912818' with duration 19 seconds will be charged for 19 seconds and cost is 0.01 (1x1x0.02+18x1x0.02^2) by rate 2487323 using -580360628 as seed Jan 29 11:52:42: Setting up a new charge with tariff 'verizon-PRE' ... Jan 29 11:52:42: Checked 2010-01-29 20:52:22 Europe/Zurich against 'hr{17-7} wd{mo-fr }, wd{sa su }, md{25} mo{dec}, md{26} mo{dec}, md{1} mo{jan}, md{2} mo{jan}, md{10} mo{apr}, md{13} mo{apr}, md{1} mo{may}, md{1} mo{jun}, md{1} mo{aug}': 1 Jan 29 11:52:42: Checked 2010-01-29 20:52:41 Europe/Zurich against 'hr{17-7} wd{mo-fr }, wd{sa su }, md{25} mo{dec}, md{26} mo{dec}, md{1} mo{jan}, md{2} mo{jan}, md{10} mo{apr}, md{13} mo{apr}, md{1} mo{may}, md{1} mo{jun}, md{1} mo{aug}': 1 Jan 29 11:52:42: Start of call is peak level 1 Jan 29 11:52:42: End of call is peak level 1 Jan 29 11:52:42: PrepareNexecute 'GetPricePerDestination*' Jan 29 11:52:42: SQL query 'GetPricePerDestination*' executed in 0.001847 seconds Jan 29 11:52:42: Calculating vendor's charge by tariff 'verizon-PRE' Jan 29 11:52:42: Call to '41216912818' with duration 19 seconds will be charged for 19 seconds and cost is 0.00659 (1x1x0.2709+18x1x0.0069) by rate 3530937 using -580360628 as seed Jan 29 11:52:42: Charging account for the call Jan 29 11:52:42: Inserting CDR Jan 29 11:52:42: PrepareNexecute 'InsertAccountCDR' Jan 29 11:52:42: SQL query 'InsertAccountCDR' executed in 0.001993 seconds Jan 29 11:52:42: Charging credit account 41215500329 0.01 Jan 29 11:52:42: PrepareNexecute 'UpdateAccountBalance' Jan 29 11:52:42: SQL query 'UpdateAccountBalance' executed in 0.000854 seconds Jan 29 11:52:42: Charging account's owner for the call Jan 29 11:52:42: Charging customer 16165 'Swiss offices' 0.01 Jan 29 11:52:42: PrepareNexecute 'UpdateCustomerBalance' Jan 29 11:52:42: SQL query 'UpdateCustomerBalance' executed in 0.000876 seconds Jan 29 11:52:42: Charging vendor for the call Jan 29 11:52:42: Charging vendor 55 'Verizon' 0.00659 Jan 29 11:52:42: Inserting CDR Jan 29 11:52:42: PrepareNexecute 'InsertVendorCDR' Jan 29 11:52:42: SQL query 'InsertVendorCDR' executed in 0.001083 seconds Jan 29 11:52:42: PrepareNexecute 'UpdateVendorBalance' Jan 29 11:52:42: SQL query 'UpdateVendorBalance' executed in 0.000807 seconds Jan 29 11:52:42: Accounting response Jan 29 11:52:42: ...Done Accounting/Stop/originate/VoIP in 0.031040 seconds, 0.012158 spent in SQL queries. --REQUEST CALL-- Jan 29 11:53:02: Removing call 348E9091 16046E71 2DA23176 43B5D459/1 Jan 29 11:53:02: Scheduling 41215500329 for logout, call lifetime reduced to 15 Jan 29 11:53:02: PrepareNexecute 'GetSessions' Jan 29 11:53:02: SQL query 'GetSessions' executed in 0.000517 seconds Jan 29 11:53:02: Logging out account '41215500329'(58048) from '348E9091 16046E71 2DA23176 43B5D459' Jan 29 11:53:02: PrepareNexecute 'RemoveSession' Jan 29 11:53:02: SQL query 'RemoveSession' executed in 0.000597 seconds Jan 29 11:53:02: Cleaning up the call Jan 29 11:53:02: Usernames in all accounting requests are ok Jan 29 11:53:02: Processing originate/VoIP call leg Jan 29 11:53:02: Skipping Start accounting Jan 29 11:53:02: Processing answer/VoIP call leg Jan 29 11:53:02: Processing originate/VoIP call leg Jan 29 11:53:02: Processing answer/VoIP call leg Jan 29 11:53:02: Skipping Start accounting Jan 29 11:53:02: There are no unsaved CDRs for this call left Jan 29 11:53:02: Call '348E9091 16046E71 2DA23176 43B5D459/1' deleted from the cache Jan 29 11:53:02: Call 348E9091 16046E71 2DA23176 43B5D459/1 removed --CALL