Current-time: Feb 01 06:04:14 PST (UTC -0800) H323-conf-id: 1D90C352 501D270A 666AD51E 40372E72 SIP Call-ID: 94.23.225.212-1264800587.36 SIP Call-ID: 94.23.242.200-1264800587.148 Requests: 4 REQUEST-- Jan 29 13:30:17: Processing request (BE ver1.245.2.11,pid15598): NAS-IP-Address = '94.23.225.212' User-Name = '94.23.242.200' Called-Station-Id = '+41216912818' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Stop' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '21:29:47 GMT Fri Jan 29 2010' h323-connect-time = '21:29:54 GMT Fri Jan 29 2010' h323-disconnect-time = '21:30:17 GMT Fri Jan 29 2010' h323-disconnect-cause = '10' h323-conf-id = '1D90C352 501D270A 666AD51E 40372E72' call-id = '94.23.225.212-1264800587.36' Acct-Session-Time = '23' session-protocol = 'sipv2' h323-remote-address = '212.249.15.9' Exec-Program-Log = 'porta-billing.pl' Jan 29 13:30:17: h323-conf-id=1D90C352 501D270A 666AD51E 40372E72/1, call-id=94.23.225.212-1264800587.36/1 Jan 29 13:30:17: H323/SIP call, use h323-conf-id, but remember call-id Jan 29 13:30:17: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 13:30:17: SQL query 'GetActiveLegIdByAcct' executed in 0.001311 seconds Jan 29 13:30:17: User-Name needs correction. Postponing. Jan 29 13:30:17: Accounting response Jan 29 13:30:17: ...Done Accounting/Stop/originate/VoIP in 0.005821 seconds, 0.001311 spent in SQL queries. --REQUEST REQUEST-- Jan 29 13:30:17: Processing request (BE ver1.245.2.11,pid15598): NAS-IP-Address = '94.23.225.212' User-Name = '94.23.242.200' Called-Station-Id = '41216912818' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Stop' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '21:29:47 GMT Fri Jan 29 2010' h323-connect-time = '21:29:54 GMT Fri Jan 29 2010' h323-disconnect-time = '21:30:17 GMT Fri Jan 29 2010' h323-disconnect-cause = '10' h323-conf-id = '1D90C352 501D270A 666AD51E 40372E72' call-id = '94.23.225.212-1264800587.36' Acct-Session-Time = '23' session-protocol = 'sipv2' h323-remote-address = '94.23.242.200' Exec-Program-Log = 'porta-billing.pl' Jan 29 13:30:17: h323-conf-id=1D90C352 501D270A 666AD51E 40372E72/1, call-id=94.23.225.212-1264800587.36/1 Jan 29 13:30:17: Found a call in cache with such id Jan 29 13:30:17: Copying randomization seed '26049' into request's PortaBilling_Seed attribute Jan 29 13:30:17: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 13:30:17: SQL query 'GetActiveLegIdByAcct' executed in 0.00182 seconds Jan 29 13:30:17: User-Name needs correction. Postponing. Jan 29 13:30:17: Accounting response Jan 29 13:30:17: ...Done Accounting/Stop/answer/VoIP in 0.007207 seconds, 0.001820 spent in SQL queries. --REQUEST REQUEST-- Jan 29 13:30:34: Processing request (BE ver1.245.2.11,pid15598): NAS-IP-Address = '94.23.242.200' User-Name = '41215500329' Called-Station-Id = '+41216912818' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Start' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '21:29:47 GMT Fri Jan 29 2010' h323-conf-id = '1D90C352 501D270A 666AD51E 40372E72' call-id = '94.23.242.200-1264800587.148' session-protocol = 'sipv2' h323-remote-address = '94.23.225.212' Exec-Program-Log = 'porta-billing.pl' Jan 29 13:30:34: fixup: Using value '21:29:47 GMT Fri Jan 29 2010' to supply missing h323-connect-time attribute in Start accounting Jan 29 13:30:34: h323-conf-id=1D90C352 501D270A 666AD51E 40372E72/1, call-id=94.23.242.200-1264800587.148/1 Jan 29 13:30:34: Found a call in cache with such id Jan 29 13:30:34: Fixing time with duration 0 seconds from connect time Jan 29 13:30:34: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 13:30:34: SQL query 'GetActiveLegIdByAcct' executed in 0.001583 seconds Jan 29 13:30:34: PrepareNexecute 'AccountAccounting' Jan 29 13:30:34: SQL query 'AccountAccounting' executed in 0.001782 seconds Jan 29 13:30:34: Found Account: 41215500329[58048,credit,balance=0.33000,limit=none] of customer Swiss offices[16165,balance=633.61000,limit=700.00000] Jan 29 13:30:34: Looking up vendor/connection Jan 29 13:30:34: Trying to match connection for call Jan 29 13:30:34: Looking for a connection VoIP/originate Jan 29 13:30:34: Outgoing VoIP, matching by the remote IP address '94.23.225.212' (env 1) Jan 29 13:30:34: Call goes to our trusted node astrad.switzernet.com, on net leg Jan 29 13:30:34: Connection to vendor not found Jan 29 13:30:34: PrepareNexecute 'InsertActiveLeg' Jan 29 13:30:34: SQL query 'InsertActiveLeg' executed in 0.000955 seconds Jan 29 13:30:34: Accounting response Jan 29 13:30:34: ...Done Accounting/Start/originate/VoIP in 0.013933 seconds, 0.004320 spent in SQL queries. --REQUEST CALL-- Jan 29 13:30:49: Removing call 1D90C352 501D270A 666AD51E 40372E72/1 Jan 29 13:30:49: No logged in accounts, call lifetime reduced to 15 Jan 29 13:30:49: Cleaning up the call Jan 29 13:30:49: Attempt to fix usernames for 2 requests Jan 29 13:30:49: Changing '94.23.242.200' -> '41215500329' Jan 29 13:30:49: Copying randomization seed '26049' into request's PortaBilling_Seed attribute Jan 29 13:30:49: Copied account: 41215500329[58048,credit,balance=0.33000,limit=none] of customer Swiss offices[16165,balance=633.61000,limit=700.00000] into the fixed request Jan 29 13:30:49: Changing '94.23.242.200' -> '41215500329' Jan 29 13:30:49: Copying randomization seed '26049' into request's PortaBilling_Seed attribute Jan 29 13:30:49: Copied account: 41215500329[58048,credit,balance=0.33000,limit=none] of customer Swiss offices[16165,balance=633.61000,limit=700.00000] into the fixed request Jan 29 13:30:49: Processing originate/VoIP call leg Jan 29 13:30:49: Found not billed accounting request with the duration more than zero - bill it now Jan 29 13:30:49: Looking up vendor/connection Jan 29 13:30:49: Trying to match connection for call Jan 29 13:30:49: Looking for a connection VoIP/originate Jan 29 13:30:49: Outgoing VoIP, matching by the remote IP address '212.249.15.9' (env 1) Jan 29 13:30:49: Found connection 217 'OpenSER 9' to vendor 'Verizon' Jan 29 13:30:49: Found vendor/connection Jan 29 13:30:49: Applying connection translation rule on CLD ... Jan 29 13:30:49: Translation 's/^\+//;' applied: '+41216912818' -> '41216912818' Jan 29 13:30:49: Charging call ... Jan 29 13:30:49: Setting up a new charge with tariff 'business' ... Jan 29 13:30:49: Using peak rate, since no off-peak is defined Jan 29 13:30:49: PrepareNexecute 'GetPricePerDestination*' Jan 29 13:30:49: SQL query 'GetPricePerDestination*' executed in 0.001578 seconds Jan 29 13:30:49: Calculating account's charge by tariff 'business' Jan 29 13:30:49: Call to '41216912818' with duration 23 seconds will be charged for 23 seconds and cost is 0.01 (1x1x0.02+22x1x0.02^2) by rate 2487323 using 66681 as seed Jan 29 13:30:49: Setting up a new charge with tariff 'verizon-PRE' ... Jan 29 13:30:49: Checked 2010-01-29 22:29:54 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 13:30:49: Checked 2010-01-29 22:30:17 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 13:30:49: Start of call is peak level 1 Jan 29 13:30:49: End of call is peak level 1 Jan 29 13:30:49: PrepareNexecute 'GetPricePerDestination*' Jan 29 13:30:49: SQL query 'GetPricePerDestination*' executed in 0.001975 seconds Jan 29 13:30:49: Calculating vendor's charge by tariff 'verizon-PRE' Jan 29 13:30:49: Call to '41216912818' with duration 23 seconds will be charged for 23 seconds and cost is 0.00705 (1x1x0.2709+22x1x0.0069) by rate 3530937 using 66681 as seed Jan 29 13:30:49: Charging account for the call Jan 29 13:30:49: Inserting CDR Jan 29 13:30:49: PrepareNexecute 'InsertAccountCDR' Jan 29 13:30:49: SQL query 'InsertAccountCDR' executed in 0.001358 seconds Jan 29 13:30:49: Charging credit account 41215500329 0.01 Jan 29 13:30:49: PrepareNexecute 'UpdateAccountBalance' Jan 29 13:30:49: SQL query 'UpdateAccountBalance' executed in 0.000868 seconds Jan 29 13:30:49: Charging account's owner for the call Jan 29 13:30:49: Charging customer 16165 'Swiss offices' 0.01 Jan 29 13:30:49: PrepareNexecute 'UpdateCustomerBalance' Jan 29 13:30:49: SQL query 'UpdateCustomerBalance' executed in 0.001077 seconds Jan 29 13:30:49: Charging vendor for the call Jan 29 13:30:49: Charging vendor 55 'Verizon' 0.00705 Jan 29 13:30:49: Inserting CDR Jan 29 13:30:49: PrepareNexecute 'InsertVendorCDR' Jan 29 13:30:49: SQL query 'InsertVendorCDR' executed in 0.001101 seconds Jan 29 13:30:49: PrepareNexecute 'UpdateVendorBalance' Jan 29 13:30:49: SQL query 'UpdateVendorBalance' executed in 0.001021 seconds Jan 29 13:30:49: Processing answer/VoIP call leg Jan 29 13:30:49: Found not billed accounting request with the duration more than zero - bill it now Jan 29 13:30:49: Looking up vendor/connection Jan 29 13:30:49: Trying to match connection for call Jan 29 13:30:49: Looking for a connection VoIP/answer Jan 29 13:30:49: VoIP, matching by the node IP '94.23.225.212' and User-Name '94.23.242.200' Jan 29 13:30:49: No VoIP from vendor connections were found Jan 29 13:30:49: Connection to vendor not found Jan 29 13:30:49: Charging call ... Jan 29 13:30:49: This is incoming call, bill only vendor Jan 29 13:30:49: Vendor is undefined (on-net call?), call is not billed Jan 29 13:30:49: Processing originate/VoIP call leg Jan 29 13:30:49: Skipping Start accounting Jan 29 13:30:49: There are no unsaved CDRs for this call left Jan 29 13:30:49: Call '1D90C352 501D270A 666AD51E 40372E72/1' deleted from the cache Jan 29 13:30:49: Call 1D90C352 501D270A 666AD51E 40372E72/1 removed --CALL REQUEST-- Jan 29 13:31:15: Processing request (BE ver1.245.2.11,pid15598): NAS-IP-Address = '94.23.242.200' User-Name = '41215500329' Called-Station-Id = '0216912818' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Start' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '21:29:47 GMT Fri Jan 29 2010' h323-conf-id = '1D90C352 501D270A 666AD51E 40372E72' call-id = '94.23.242.200-1264800587.148' session-protocol = 'sipv2' h323-remote-address = '94.23.242.200' Exec-Program-Log = 'porta-billing.pl' Jan 29 13:31:15: fixup: Using value '21:29:47 GMT Fri Jan 29 2010' to supply missing h323-connect-time attribute in Start accounting Jan 29 13:31:15: h323-conf-id=1D90C352 501D270A 666AD51E 40372E72/1, call-id=94.23.242.200-1264800587.148/1 Jan 29 13:31:15: H323/SIP call, use h323-conf-id, but remember call-id Jan 29 13:31:15: Fixing time with duration 0 seconds from connect time Jan 29 13:31:15: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 13:31:15: SQL query 'GetActiveLegIdByAcct' executed in 0.001114 seconds Jan 29 13:31:15: PrepareNexecute 'AccountAccounting' Jan 29 13:31:15: SQL query 'AccountAccounting' executed in 0.002119 seconds Jan 29 13:31:15: Found Account: 41215500329[58048,credit,balance=0.34000,limit=none] of customer Swiss offices[16165,balance=633.62000,limit=700.00000] Jan 29 13:31:15: Looking up vendor/connection Jan 29 13:31:15: Trying to match connection for call Jan 29 13:31:15: Looking for a connection VoIP/answer Jan 29 13:31:15: VoIP, matching by the node IP '94.23.242.200' and User-Name '41215500329' Jan 29 13:31:15: No VoIP from vendor connections were found Jan 29 13:31:15: Connection to vendor not found Jan 29 13:31:15: PrepareNexecute 'InsertActiveLeg' Jan 29 13:31:15: SQL query 'InsertActiveLeg' executed in 0.000912 seconds Jan 29 13:31:15: Accounting response Jan 29 13:31:15: ...Done Accounting/Start/answer/VoIP in 0.011634 seconds, 0.004145 spent in SQL queries. --REQUEST CALL-- Jan 29 13:33:24: Removing call 1D90C352 501D270A 666AD51E 40372E72/1 Jan 29 13:33:24: No logged in accounts, call lifetime reduced to 15 Jan 29 13:33:24: Cleaning up the call Jan 29 13:33:24: Usernames in all accounting requests are ok Jan 29 13:33:24: Processing answer/VoIP call leg Jan 29 13:33:24: Skipping Start accounting Jan 29 13:33:24: No outgoing connections to vendor, on-net call Jan 29 13:33:24: No originate call legs, junk incoming call Jan 29 13:33:24: Call '1D90C352 501D270A 666AD51E 40372E72/1' deleted from the cache Jan 29 13:33:24: Call 1D90C352 501D270A 666AD51E 40372E72/1 removed --CALL