Current-time: Jul 25 01:32:02 PDT (UTC -0700) H323-conf-id: 165DB681 59729372 12D0EAA7 3FB42ACF SIP Call-ID: 91.121.151.58-1311582579.90 SIP Call-ID: 94.23.225.212-1311582578.124 Requests: 12 REQUEST-- ul 25 01:29:39: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '94.23.225.212' NAS-Port-Name = 'SIP/41215500329-f400c390' User-Name = '41215500329' Called-Station-Id = '0215500327' Calling-Station-Id = '41215500329' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '94.23.225.212-1311582578.124' Digest-Attributes = 'User-Name = "41215500329"' Digest-Attributes = 'Realm = "switzernet"' Digest-Attributes = 'Nonce = "1356c229"' Digest-Attributes = 'URI = "sip:0215500327@astrad.switzernet.com;user=phone"' Digest-Attributes = 'Method = "INVITE"' Digest-Attributes = 'Algorithm = "MD5"' Digest-Response = '621001da3420a8b221819e0ac8e18ed5' h323-remote-address = '81.62.23.131' h323-ivr-out = 'PortaBilling_Routing:SIP' Jul 25 01:29:39: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=94.23.225.212-1311582578.124/1 Jul 25 01:29:39: H323/SIP call, use h323-conf-id, but remember call-id Jul 25 01:29:39: Checking if this call comes through a VoIP from vendor connection Jul 25 01:29:39: No VoIP from vendor connections were found Jul 25 01:29:39: PrepareNexecute 'AccountAuth' Jul 25 01:29:39: SQL query 'AccountAuth' executed in 0.001806 seconds Jul 25 01:29:39: Found Account: 41215500329[58048,credit,balance=343.69000,limit=none] of customer Swiss offices[16165,balance=1536.94000,limit=2220.00000] Jul 25 01:29:39: PrepareNexecute 'GetSessions' Jul 25 01:29:39: SQL query 'GetSessions' executed in 0.000585 seconds Jul 25 01:29:39: Account 41215500329 is already logged in, other session with call ID=2129AF17 60390377 2722CBBF 613CEA4D Jul 25 01:29:39: Verification of password using method 'digest_response': success Jul 25 01:29:39: PrepareNexecute 'GetAttributeValues' Jul 25 01:29:39: SQL query 'GetAttributeValues' executed in 0.006622 seconds Jul 25 01:29:39: Applying 'clir' service check translation rule on CLD ... Jul 25 01:29:39: Translation 's/^\*81/Y/; # hide=*81' applied: '0215500327' unchanged Jul 25 01:29:39: Applying customer dialing translation rule on CLD ... Jul 25 01:29:39: Translation 'local_to_e164($_,{cc=>'41',dp=>'0',ip=>'00'});#% cc=41 dp=0 ip=00' applied: '0215500327' -> '41215500327' Jul 25 01:29:39: PrepareNexecute 'AccountAuth' Jul 25 01:29:39: SQL query 'AccountAuth' executed in 0.001815 seconds Jul 25 01:29:39: CLD '41215500327' matching our account Jul 25 01:29:39: Setting up a new charge with tariff 'business' ... Jul 25 01:29:39: Using peak rate, since no off-peak is defined Jul 25 01:29:39: PrepareNexecute 'GetPricePerDestination*' Jul 25 01:29:39: SQL query 'GetPricePerDestination*' executed in 0.002036 seconds Jul 25 01:29:39: Compute maximum call duration for leg Account 41215500329 to destination with funds 683.06 (customer funds 683.06) Jul 25 01:29:39: Maximum call duration: unlimited announced as unlimited (-1s...) by rate 3429881 using 40084 as seed Jul 25 01:29:39: Applying 'clir' service check translation rule on CLD ... Jul 25 01:29:39: Translation 's/^\*81/Y/; # hide=*81' applied: '0215500327' unchanged Jul 25 01:29:39: Local termination 'PortaSIP': Checking follow-me for 41215500327 ... Jul 25 01:29:39: PrepareNexecute 'GetAccountFollowMe' Jul 25 01:29:39: SQL query 'GetAccountFollowMe' executed in 0.000636 seconds Jul 25 01:29:39: Local termination 'PortaSIP': ... follow-me result list for 41215500327: |41215500327(acct);unlimited Jul 25 01:29:39: PrepareNexecute 'GetSipServerAddress' Jul 25 01:29:39: SQL query 'GetSipServerAddress' executed in 0.000787 seconds Jul 25 01:29:39: CLD '41215500327' found registered on 91.121.151.58. Jul 25 01:29:39: Use RTP Proxy according to policy 'Undetermined' => 'On Nat': Calling party NOT behind NAT, called party behind NAT Jul 25 01:29:39: Enhance lifetime with 1800s to Mon Jul 25 01:59:39 2011 Jul 25 01:29:39: Authentication acknowledge response h323-ivr-in = PortaBilling_Routing:@;g-hunt=seq h323-ivr-in = PortaBilling_Routing: 41215500327@91.121.151.58;expires=300;credit-time=-1;forward-on-fail=yes;rtpp=3;moh=1;patience=20 h323-billing-model = 0 h323-ivr-in = Tariff:business h323-ivr-in = PortaBilling_CLI:41215500329 h323-ivr-in = MOH:1 h323-ivr-in = PortaBilling_Account:YES h323-ivr-in = PortaBilling_CompleteNumber:41215500327 h323-ivr-in = PortaBilling_Auth_CLD:41215500327 h323-ivr-in = PortaBilling_Auth_Reseller_CLD:41215500327 h323-return-code = 13 h323-currency = CHF h323-preferred-lang = en Jul 25 01:29:39: ...Done Authorize/INVITE in 0.032718 seconds, 0.014287 spent in SQL queries. --REQUEST REQUEST-- Jul 25 01:29:40: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '91.121.151.58' NAS-Port-Name = 'SIP/94.23.225.212-007f8d00' User-Name = '94.23.225.212' Called-Station-Id = '41215500327' Calling-Station-Id = '41215500329' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '91.121.151.58-1311582579.90' Password = 'cisco' h323-remote-address = '94.23.225.212' h323-ivr-out = 'PortaBilling_Routing:SIP' Jul 25 01:29:40: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=91.121.151.58-1311582579.90/1 Jul 25 01:29:40: Found a call in cache with such id Jul 25 01:29:40: Authorization of the trusted node Jul 25 01:29:40: IP based authorization, force 'plaintext' password verification Jul 25 01:29:40: Verification of password using method 'plaintext': success Jul 25 01:29:40: '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 Jul 25 01:29:40: PrepareNexecute 'AccountAuth' Jul 25 01:29:40: SQL query 'AccountAuth' executed in 0.001862 seconds Jul 25 01:29:40: CLD '41215500327' matching our account Jul 25 01:29:40: Local termination 'PortaSIP', after previous hop from PortaSIP node Jul 25 01:29:40: PrepareNexecute 'GetSipServerAddress' Jul 25 01:29:40: SQL query 'GetSipServerAddress' executed in 0.001558 seconds Jul 25 01:29:40: CLD '41215500327' found registered on 91.121.151.58. Jul 25 01:29:40: Don't use RTP Proxy, local policy not applied. Jul 25 01:29:40: Authentication acknowledge response h323-ivr-in = PortaBilling_Routing:@;g-hunt=seq h323-ivr-in = PortaBilling_Routing: 41215500327@91.121.151.58;expires=300;credit-time=-1;patience=20 h323-ivr-in = PortaBilling_CacheExpiration:Never h323-ivr-in = PortaBilling_CLI:41215500329 h323-ivr-in = PortaBilling_Account:YES h323-ivr-in = PortaBilling_CompleteNumber:41215500327 h323-ivr-in = PortaBilling_Auth_CLD:41215500327 h323-ivr-in = PortaBilling_Auth_Reseller_CLD:41215500327 h323-return-code = 0 Jul 25 01:29:40: ...Done Authorize in 0.011717 seconds, 0.003420 spent in SQL queries. --REQUEST REQUEST-- Jul 25 01:29:43: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '94.23.225.212' User-Name = '41215500329' Called-Station-Id = '' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Start' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '08:29:39 GMT Mon Jul 25 2011' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '94.23.225.212-1311582578.124' session-protocol = 'sipv2' h323-remote-address = '91.121.151.58' Exec-Program-Log = 'porta-billing.pl' Jul 25 01:29:43: fixup: Using value '08:29:39 GMT Mon Jul 25 2011' to supply missing h323-connect-time attribute in Start accounting Jul 25 01:29:43: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=94.23.225.212-1311582578.124/1 Jul 25 01:29:43: Found a call in cache with such id Jul 25 01:29:43: Copied account: 41215500329[58048,credit,balance=343.69000,limit=none] of customer Swiss offices[16165,balance=1536.94000,limit=2220.00000] from '94.23.225.212' into the current request Jul 25 01:29:43: Fixing time with duration 0 seconds from connect time Jul 25 01:29:43: PrepareNexecute 'GetActiveLegIdByAcct' Jul 25 01:29:43: SQL query 'GetActiveLegIdByAcct' executed in 0.00124 seconds Jul 25 01:29:43: Looking up vendor/connection Jul 25 01:29:43: Trying to match connection for call Jul 25 01:29:43: Looking for a connection VoIP/originate Jul 25 01:29:43: Outgoing VoIP, matching by the remote IP address '91.121.151.58' (env 1) Jul 25 01:29:43: Call goes to our trusted node astrad15.switzernet.com, on net leg Jul 25 01:29:43: Connection to vendor not found Jul 25 01:29:43: PrepareNexecute 'InsertActiveLeg' Jul 25 01:29:43: SQL query 'InsertActiveLeg' executed in 0.000877 seconds Jul 25 01:29:43: Accounting response Jul 25 01:29:43: ...Done Accounting/Start/originate/VoIP in 0.007942 seconds, 0.002117 spent in SQL queries. --REQUEST REQUEST-- Jul 25 01:29:43: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '94.23.225.212' User-Name = '41215500329' Called-Station-Id = '' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Stop' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '08:29:39 GMT Mon Jul 25 2011' h323-connect-time = '08:29:39 GMT Mon Jul 25 2011' h323-disconnect-time = '08:29:39 GMT Mon Jul 25 2011' h323-disconnect-cause = '10' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '94.23.225.212-1311582578.124' Acct-Session-Time = '0' session-protocol = 'sipv2' h323-remote-address = 'sip-ua' Exec-Program-Log = 'porta-billing.pl' Jul 25 01:29:43: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=94.23.225.212-1311582578.124/1 Jul 25 01:29:43: Found a call in cache with such id Jul 25 01:29:43: Copied account: 41215500329[58048,credit,balance=343.69000,limit=none] of customer Swiss offices[16165,balance=1536.94000,limit=2220.00000] from '94.23.225.212' into the current request Jul 25 01:29:43: PrepareNexecute 'GetActiveLegIdByAcct' Jul 25 01:29:43: SQL query 'GetActiveLegIdByAcct' executed in 0.001285 seconds Jul 25 01:29:43: End of the outgoing call for account, which appears as never logged-in Jul 25 01:29:43: Set lifetime with 15s to Mon Jul 25 01:29:58 2011 Jul 25 01:29:43: Looking up vendor/connection Jul 25 01:29:43: Trying to match connection for call Jul 25 01:29:43: Looking for a connection VoIP/originate Jul 25 01:29:43: Outgoing VoIP, matching by the remote IP address 'SIP-UA' (env 1) Jul 25 01:29:43: Found connection 154 'SIP UA <-> SIP UA' to vendor 'Switzernet' Jul 25 01:29:43: Found vendor/connection Jul 25 01:29:43: PrepareNexecute 'GetEnvMail' Jul 25 01:29:43: SQL query 'GetEnvMail' executed in 0.0003 seconds Jul 25 01:29:43: PrepareNexecute 'MailAlarm' Jul 25 01:29:43: SQL query 'MailAlarm' executed in 0.032136 seconds Jul 25 01:29:43: There are no recepients of mail alarms with type 'UNDEF_CLD' Jul 25 01:29:43: Applying connection translation rule on CLD ... Jul 25 01:29:43: Translation 's/^00//; s/^0/41/;' applied: 'unknown' unchanged Jul 25 01:29:43: Charging call ... Jul 25 01:29:43: Zero duration call Jul 25 01:29:43: Initialize new charge clone with tariff 'business' as this one is already initialized with incompatible parameters Jul 25 01:29:43: Setting up a new charge with tariff 'business' ... Jul 25 01:29:43: Using peak rate, since no off-peak is defined Jul 25 01:29:43: PrepareNexecute 'GetPricePerDestination*' Jul 25 01:29:43: SQL query 'GetPricePerDestination*' executed in 0.016611 seconds Jul 25 01:29:43: Charge setup: No rates found for number 'unknown' in tariff 156 'business' Jul 25 01:29:43: Calculating account's charge by tariff 'business' Jul 25 01:29:43: Unable to compute call cost: No rates found for number 'unknown' in tariff 156 'business' Jul 25 01:29:43: Setting up a new charge with tariff 'SIP Termination' ... Jul 25 01:29:43: Using peak rate, since no off-peak is defined Jul 25 01:29:43: PrepareNexecute 'GetPricePerDestination*' Jul 25 01:29:43: SQL query 'GetPricePerDestination*' executed in 0.001305 seconds Jul 25 01:29:43: Charge setup: No rates found for number 'unknown' in tariff 215 'SIP Termination' Jul 25 01:29:43: Calculating vendor's charge by tariff 'SIP Termination' Jul 25 01:29:43: Unable to compute call cost: No rates found for number 'unknown' in tariff 215 'SIP Termination' Jul 25 01:29:43: Updating account usage of '41215500329' with 'Mon Jul 25 01:29:43 2011' Jul 25 01:29:43: PrepareNexecute 'UpdateAccountUsage' Jul 25 01:29:43: SQL query 'UpdateAccountUsage' executed in 0.001083 seconds Jul 25 01:29:43: Charging vendor for the call Jul 25 01:29:43: Inserting fail CDR Jul 25 01:29:43: PrepareNexecute 'InsertVendorCDRFail' Jul 25 01:29:43: SQL query 'InsertVendorCDRFail' executed in 0.001012 seconds Jul 25 01:29:43: Accounting response Jul 25 01:29:43: ...Done Accounting/Stop/originate/VoIP in 0.069371 seconds, 0.053732 spent in SQL queries. --REQUEST REQUEST-- Jul 25 01:29:43: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '91.121.151.58' User-Name = '94.23.225.212' Called-Station-Id = '' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Start' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '08:29:40 GMT Mon Jul 25 2011' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '91.121.151.58-1311582579.90' session-protocol = 'sipv2' h323-remote-address = 'sip-ua' Exec-Program-Log = 'porta-billing.pl' Jul 25 01:29:43: fixup: Using value '08:29:40 GMT Mon Jul 25 2011' to supply missing h323-connect-time attribute in Start accounting Jul 25 01:29:43: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=91.121.151.58-1311582579.90/1 Jul 25 01:29:43: Found a call in cache with such id Jul 25 01:29:43: Copying randomization seed '15847' into request's PortaBilling_Seed attribute Jul 25 01:29:43: Copying originator authorized CLD '41215500327' into current request Jul 25 01:29:43: Copying reseller authorized CLD '41215500327' into current request Jul 25 01:29:43: Replacing username '94.23.225.212' with the real username '41215500329' Jul 25 01:29:43: Copied account: 41215500329[58048,credit,balance=343.69000,limit=none] of customer Swiss offices[16165,balance=1536.94000,limit=2220.00000] from '94.23.225.212' into the current request Jul 25 01:29:43: Fixing time with duration 0 seconds from connect time Jul 25 01:29:43: PrepareNexecute 'GetActiveLegIdByAcct' Jul 25 01:29:43: SQL query 'GetActiveLegIdByAcct' executed in 0.00092 seconds Jul 25 01:29:43: Looking up vendor/connection Jul 25 01:29:43: Trying to match connection for call Jul 25 01:29:43: Looking for a connection VoIP/originate Jul 25 01:29:43: Outgoing VoIP, matching by the remote IP address 'SIP-UA' (env 1) Jul 25 01:29:43: Found connection 154 'SIP UA <-> SIP UA' to vendor 'Switzernet' Jul 25 01:29:43: Found vendor/connection Jul 25 01:29:43: PrepareNexecute 'InsertActiveLeg' Jul 25 01:29:43: SQL query 'InsertActiveLeg' executed in 0.001048 seconds Jul 25 01:29:43: Accounting response Jul 25 01:29:43: ...Done Accounting/Start/originate/VoIP in 0.008287 seconds, 0.001968 spent in SQL queries. --REQUEST REQUEST-- Jul 25 01:29:43: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '91.121.151.58' User-Name = '94.23.225.212' Called-Station-Id = '' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Stop' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '08:29:40 GMT Mon Jul 25 2011' h323-connect-time = '08:29:40 GMT Mon Jul 25 2011' h323-disconnect-time = '08:29:40 GMT Mon Jul 25 2011' h323-disconnect-cause = '10' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '91.121.151.58-1311582579.90' Acct-Session-Time = '0' session-protocol = 'sipv2' h323-remote-address = 'sip-ua' Exec-Program-Log = 'porta-billing.pl' Jul 25 01:29:43: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=91.121.151.58-1311582579.90/1 Jul 25 01:29:43: Found a call in cache with such id Jul 25 01:29:43: Copying randomization seed '15847' into request's PortaBilling_Seed attribute Jul 25 01:29:43: Copying originator authorized CLD '41215500327' into current request Jul 25 01:29:43: Copying reseller authorized CLD '41215500327' into current request Jul 25 01:29:43: Replacing username '94.23.225.212' with the real username '41215500329' Jul 25 01:29:43: Copied account: 41215500329[58048,credit,balance=343.69000,limit=none] of customer Swiss offices[16165,balance=1536.94000,limit=2220.00000] from '94.23.225.212' into the current request Jul 25 01:29:43: PrepareNexecute 'GetActiveLegIdByAcct' Jul 25 01:29:43: SQL query 'GetActiveLegIdByAcct' executed in 0.001052 seconds Jul 25 01:29:43: PrepareNexecute 'DeleteActiveLeg' Jul 25 01:29:43: SQL query 'DeleteActiveLeg' executed in 0.000977 seconds Jul 25 01:29:43: End of the outgoing call for account, which appears as never logged-in Jul 25 01:29:43: Set lifetime with 15s to Mon Jul 25 01:29:58 2011 Jul 25 01:29:43: Looking up vendor/connection Jul 25 01:29:43: Trying to match connection for call Jul 25 01:29:43: Looking for a connection VoIP/originate Jul 25 01:29:43: Outgoing VoIP, matching by the remote IP address 'SIP-UA' (env 1) Jul 25 01:29:43: Found connection 154 'SIP UA <-> SIP UA' to vendor 'Switzernet' Jul 25 01:29:43: Found vendor/connection Jul 25 01:29:43: PrepareNexecute 'MailAlarm' Jul 25 01:29:43: SQL query 'MailAlarm' executed in 0.000234 seconds Jul 25 01:29:43: There are no recepients of mail alarms with type 'UNDEF_CLD' Jul 25 01:29:43: Applying connection translation rule on CLD ... Jul 25 01:29:43: Translation 's/^00//; s/^0/41/;' applied: 'unknown' unchanged Jul 25 01:29:43: Charging call ... Jul 25 01:29:43: Zero duration call Jul 25 01:29:43: Initialize new charge clone with tariff 'business' as this one is already initialized with incompatible parameters Jul 25 01:29:43: Setting up a new charge with tariff 'business' ... Jul 25 01:29:43: Using peak rate, since no off-peak is defined Jul 25 01:29:43: PrepareNexecute 'GetPricePerDestination*' Jul 25 01:29:43: SQL query 'GetPricePerDestination*' executed in 0.001639 seconds Jul 25 01:29:43: Calculating account's charge by tariff 'business' Jul 25 01:29:43: Call to '41215500327' with duration 0 seconds will be charged for 0 seconds and cost is 0 (0s<1s) by rate 3429881 using 40084 as seed Jul 25 01:29:43: Setting up a new charge with tariff 'SIP Termination' ... Jul 25 01:29:43: Using peak rate, since no off-peak is defined Jul 25 01:29:43: PrepareNexecute 'GetPricePerDestination*' Jul 25 01:29:43: SQL query 'GetPricePerDestination*' executed in 0.001595 seconds Jul 25 01:29:43: Charge setup: No rates found for number 'unknown' in tariff 215 'SIP Termination' Jul 25 01:29:43: Calculating vendor's charge by tariff 'SIP Termination' Jul 25 01:29:43: Unable to compute call cost: No rates found for number 'unknown' in tariff 215 'SIP Termination' Jul 25 01:29:43: Updating account usage of '41215500329' with 'Mon Jul 25 01:29:43 2011' Jul 25 01:29:43: PrepareNexecute 'UpdateAccountUsage' Jul 25 01:29:43: SQL query 'UpdateAccountUsage' executed in 0.000478 seconds Jul 25 01:29:43: Charging vendor for the call Jul 25 01:29:43: Inserting fail CDR Jul 25 01:29:43: PrepareNexecute 'InsertVendorCDRFail' Jul 25 01:29:43: SQL query 'InsertVendorCDRFail' executed in 0.001033 seconds Jul 25 01:29:43: Accounting response Jul 25 01:29:43: ...Done Accounting/Stop/originate/VoIP in 0.023238 seconds, 0.007008 spent in SQL queries. --REQUEST REQUEST-- Jul 25 01:29:43: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '94.23.225.212' User-Name = '41215500329' Called-Station-Id = '0215500327' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Start' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '08:29:38 GMT Mon Jul 25 2011' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '94.23.225.212-1311582578.124' session-protocol = 'sipv2' h323-remote-address = '94.23.225.212' Exec-Program-Log = 'porta-billing.pl' Jul 25 01:29:43: fixup: Using value '08:29:38 GMT Mon Jul 25 2011' to supply missing h323-connect-time attribute in Start accounting Jul 25 01:29:43: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=94.23.225.212-1311582578.124/1 Jul 25 01:29:43: Found a call in cache with such id Jul 25 01:29:43: Copied account: 41215500329[58048,credit,balance=343.69000,limit=none] of customer Swiss offices[16165,balance=1536.94000,limit=2220.00000] from '94.23.225.212' into the current request Jul 25 01:29:43: Fixing time with duration 0 seconds from connect time Jul 25 01:29:43: PrepareNexecute 'GetActiveLegIdByAcct' Jul 25 01:29:43: SQL query 'GetActiveLegIdByAcct' executed in 0.001286 seconds Jul 25 01:29:43: Looking up vendor/connection Jul 25 01:29:43: Trying to match connection for call Jul 25 01:29:43: Looking for a connection VoIP/answer Jul 25 01:29:43: VoIP, matching by the node IP '94.23.225.212' and User-Name '41215500329' Jul 25 01:29:43: No VoIP from vendor connections were found Jul 25 01:29:43: Connection to vendor not found Jul 25 01:29:43: PrepareNexecute 'InsertActiveLeg' Jul 25 01:29:43: SQL query 'InsertActiveLeg' executed in 0.000869 seconds Jul 25 01:29:43: Accounting response Jul 25 01:29:43: ...Done Accounting/Start/answer/VoIP in 0.007970 seconds, 0.002155 spent in SQL queries. --REQUEST REQUEST-- Jul 25 01:29:44: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '91.121.151.58' User-Name = '94.23.225.212' Called-Station-Id = '41215500327' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Start' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '08:29:39 GMT Mon Jul 25 2011' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '91.121.151.58-1311582579.90' session-protocol = 'sipv2' h323-remote-address = '94.23.225.212' Exec-Program-Log = 'porta-billing.pl' Jul 25 01:29:44: fixup: Using value '08:29:39 GMT Mon Jul 25 2011' to supply missing h323-connect-time attribute in Start accounting Jul 25 01:29:44: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=91.121.151.58-1311582579.90/1 Jul 25 01:29:44: Found a call in cache with such id Jul 25 01:29:44: Copying randomization seed '15847' into request's PortaBilling_Seed attribute Jul 25 01:29:44: Copying originator authorized CLD '41215500327' into current request Jul 25 01:29:44: Copying reseller authorized CLD '41215500327' into current request Jul 25 01:29:44: Replacing username '94.23.225.212' with the real username '41215500329' Jul 25 01:29:44: Copied account: 41215500329[58048,credit,balance=343.69000,limit=none] of customer Swiss offices[16165,balance=1536.94000,limit=2220.00000] from '94.23.225.212' into the current request Jul 25 01:29:44: Fixing time with duration 0 seconds from connect time Jul 25 01:29:44: PrepareNexecute 'GetActiveLegIdByAcct' Jul 25 01:29:44: SQL query 'GetActiveLegIdByAcct' executed in 0.00129 seconds Jul 25 01:29:44: Looking up vendor/connection Jul 25 01:29:44: Trying to match connection for call Jul 25 01:29:44: Looking for a connection VoIP/answer Jul 25 01:29:44: VoIP, matching by the node IP '91.121.151.58' and User-Name '94.23.225.212' Jul 25 01:29:44: No VoIP from vendor connections were found Jul 25 01:29:44: Connection to vendor not found Jul 25 01:29:44: PrepareNexecute 'InsertActiveLeg' Jul 25 01:29:44: SQL query 'InsertActiveLeg' executed in 0.00085 seconds Jul 25 01:29:44: Accounting response Jul 25 01:29:44: ...Done Accounting/Start/answer/VoIP in 0.009341 seconds, 0.002140 spent in SQL queries. --REQUEST REQUEST-- Jul 25 01:29:46: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '94.23.225.212' User-Name = '41215500329' Called-Station-Id = '' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Stop' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '08:29:39 GMT Mon Jul 25 2011' h323-connect-time = '08:29:43 GMT Mon Jul 25 2011' h323-disconnect-time = '08:29:45 GMT Mon Jul 25 2011' h323-disconnect-cause = '10' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '94.23.225.212-1311582578.124' Acct-Session-Time = '2' session-protocol = 'sipv2' h323-remote-address = '91.121.151.58' Exec-Program-Log = 'porta-billing.pl' Jul 25 01:29:46: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=94.23.225.212-1311582578.124/1 Jul 25 01:29:46: Found a call in cache with such id Jul 25 01:29:46: Copied account: 41215500329[58048,credit,balance=343.69000,limit=none] of customer Swiss offices[16165,balance=1536.94000,limit=2220.00000] from '94.23.225.212' into the current request Jul 25 01:29:46: PrepareNexecute 'GetActiveLegIdByAcct' Jul 25 01:29:46: SQL query 'GetActiveLegIdByAcct' executed in 0.001088 seconds Jul 25 01:29:46: PrepareNexecute 'DeleteActiveLeg' Jul 25 01:29:46: SQL query 'DeleteActiveLeg' executed in 0.000989 seconds Jul 25 01:29:46: End of the outgoing call for account, which appears as never logged-in Jul 25 01:29:46: Set lifetime with 15s to Mon Jul 25 01:30:01 2011 Jul 25 01:29:46: Looking up vendor/connection Jul 25 01:29:46: Trying to match connection for call Jul 25 01:29:46: Looking for a connection VoIP/originate Jul 25 01:29:46: Outgoing VoIP, matching by the remote IP address '91.121.151.58' (env 1) Jul 25 01:29:46: Call goes to our trusted node astrad15.switzernet.com, on net leg Jul 25 01:29:46: Connection to vendor not found Jul 25 01:29:46: No connection to vendor - on-net call leg Jul 25 01:29:46: Accounting response Jul 25 01:29:46: ...Done Accounting/Stop/originate/VoIP in 0.008715 seconds, 0.002077 spent in SQL queries. --REQUEST REQUEST-- Jul 25 01:29:46: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '91.121.151.58' User-Name = '94.23.225.212' Called-Station-Id = '' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Stop' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '08:29:40 GMT Mon Jul 25 2011' h323-connect-time = '08:29:43 GMT Mon Jul 25 2011' h323-disconnect-time = '08:29:45 GMT Mon Jul 25 2011' h323-disconnect-cause = '10' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '91.121.151.58-1311582579.90' Acct-Session-Time = '2' session-protocol = 'sipv2' h323-remote-address = 'sip-ua' Exec-Program-Log = 'porta-billing.pl' Jul 25 01:29:46: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=91.121.151.58-1311582579.90/1 Jul 25 01:29:46: Found a call in cache with such id Jul 25 01:29:46: Replacing username '94.23.225.212' with the real username '41215500329' Jul 25 01:29:46: Copied account: 41215500329[58048,credit,balance=343.69000,limit=none] of customer Swiss offices[16165,balance=1536.94000,limit=2220.00000] from '94.23.225.212' into the current request Jul 25 01:29:46: PrepareNexecute 'GetActiveLegIdByAcct' Jul 25 01:29:46: SQL query 'GetActiveLegIdByAcct' executed in 0.001042 seconds Jul 25 01:29:46: End of the outgoing call for account, which appears as never logged-in Jul 25 01:29:46: Set lifetime with 15s to Mon Jul 25 01:30:01 2011 Jul 25 01:29:46: Looking up vendor/connection Jul 25 01:29:46: Trying to match connection for call Jul 25 01:29:46: Looking for a connection VoIP/originate Jul 25 01:29:46: Outgoing VoIP, matching by the remote IP address 'SIP-UA' (env 1) Jul 25 01:29:46: Found connection 154 'SIP UA <-> SIP UA' to vendor 'Switzernet' Jul 25 01:29:46: Found vendor/connection Jul 25 01:29:46: PrepareNexecute 'MailAlarm' Jul 25 01:29:46: SQL query 'MailAlarm' executed in 0.000311 seconds Jul 25 01:29:46: There are no recepients of mail alarms with type 'UNDEF_CLD' Jul 25 01:29:46: Applying connection translation rule on CLD ... Jul 25 01:29:46: Translation 's/^00//; s/^0/41/;' applied: 'unknown' unchanged Jul 25 01:29:46: Charging call ... Jul 25 01:29:46: Initialize new charge clone with tariff 'business' as this one is already initialized with incompatible parameters Jul 25 01:29:46: Setting up a new charge with tariff 'business' ... Jul 25 01:29:46: Using peak rate, since no off-peak is defined Jul 25 01:29:46: PrepareNexecute 'GetPricePerDestination*' Jul 25 01:29:46: SQL query 'GetPricePerDestination*' executed in 0.001492 seconds Jul 25 01:29:46: Charge setup: No rates found for number 'unknown' in tariff 156 'business' Jul 25 01:29:46: Calculating account's charge by tariff 'business' Jul 25 01:29:46: Unable to compute call cost: No rates found for number 'unknown' in tariff 156 'business' Jul 25 01:29:46: PrepareNexecute 'MailAlarm' Jul 25 01:29:46: SQL query 'MailAlarm' executed in 0.000322 seconds Jul 25 01:29:46: There are no recepients of mail alarms with type 'MIS_DEST' Jul 25 01:29:46: Setting up a new charge with tariff 'SIP Termination' ... Jul 25 01:29:46: Using peak rate, since no off-peak is defined Jul 25 01:29:46: PrepareNexecute 'GetPricePerDestination*' Jul 25 01:29:46: SQL query 'GetPricePerDestination*' executed in 0.001581 seconds Jul 25 01:29:46: Charge setup: No rates found for number 'unknown' in tariff 215 'SIP Termination' Jul 25 01:29:46: Calculating vendor's charge by tariff 'SIP Termination' Jul 25 01:29:46: Unable to compute call cost: No rates found for number 'unknown' in tariff 215 'SIP Termination' Jul 25 01:29:46: PrepareNexecute 'MailAlarm' Jul 25 01:29:46: SQL query 'MailAlarm' executed in 0.000323 seconds Jul 25 01:29:46: There are no recepients of mail alarms with type 'MIS_DEST' Jul 25 01:29:46: Charging account for the call Jul 25 01:29:46: Inserting CDR Jul 25 01:29:46: PrepareNexecute 'InsertAccountCDR' Jul 25 01:29:46: SQL query 'InsertAccountCDR' executed in 0.001134 seconds Jul 25 01:29:46: Charging account's owner for the call Jul 25 01:29:46: Charging vendor for the call Jul 25 01:29:46: Charging vendor 32 'Switzernet' 0 Jul 25 01:29:46: Inserting CDR Jul 25 01:29:46: PrepareNexecute 'InsertVendorCDR' Jul 25 01:29:46: SQL query 'InsertVendorCDR' executed in 0.001078 seconds Jul 25 01:29:46: PrepareNexecute 'UpdateVendorBalance' Jul 25 01:29:46: SQL query 'UpdateVendorBalance' executed in 0.000412 seconds Jul 25 01:29:46: Accounting response Jul 25 01:29:46: ...Done Accounting/Stop/originate/VoIP in 0.031647 seconds, 0.007695 spent in SQL queries. --REQUEST REQUEST-- Jul 25 01:29:46: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '94.23.225.212' User-Name = '41215500329' Called-Station-Id = '0215500327' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Stop' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '08:29:38 GMT Mon Jul 25 2011' h323-connect-time = '08:29:43 GMT Mon Jul 25 2011' h323-disconnect-time = '08:29:45 GMT Mon Jul 25 2011' h323-disconnect-cause = '10' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '94.23.225.212-1311582578.124' Acct-Session-Time = '2' session-protocol = 'sipv2' h323-remote-address = '94.23.225.212' Exec-Program-Log = 'porta-billing.pl' Jul 25 01:29:46: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=94.23.225.212-1311582578.124/1 Jul 25 01:29:46: Found a call in cache with such id Jul 25 01:29:46: Copied account: 41215500329[58048,credit,balance=343.69000,limit=none] of customer Swiss offices[16165,balance=1536.94000,limit=2220.00000] from '94.23.225.212' into the current request Jul 25 01:29:46: PrepareNexecute 'GetActiveLegIdByAcct' Jul 25 01:29:46: SQL query 'GetActiveLegIdByAcct' executed in 0.006608 seconds Jul 25 01:29:46: PrepareNexecute 'DeleteActiveLeg' Jul 25 01:29:46: SQL query 'DeleteActiveLeg' executed in 0.001026 seconds Jul 25 01:29:46: End of call on incoming call leg from access NAS Jul 25 01:29:46: There have been authentication requests from more than one NAS Jul 25 01:29:46: Scheduling 41215500329 for logout, call lifetime reduced to 15 Jul 25 01:29:46: PrepareNexecute 'GetSessions' Jul 25 01:29:46: SQL query 'GetSessions' executed in 0.000516 seconds Jul 25 01:29:46: Logging out account '41215500329'(58048) from '165DB681 59729372 12D0EAA7 3FB42ACF' Jul 25 01:29:46: PrepareNexecute 'RemoveSession' Jul 25 01:29:46: SQL query 'RemoveSession' executed in 0.000436 seconds Jul 25 01:29:46: Set lifetime with 15s to Mon Jul 25 01:30:01 2011 Jul 25 01:29:46: Looking up vendor/connection Jul 25 01:29:46: Trying to match connection for call Jul 25 01:29:46: Looking for a connection VoIP/answer Jul 25 01:29:46: VoIP, matching by the node IP '94.23.225.212' and User-Name '41215500329' Jul 25 01:29:46: No VoIP from vendor connections were found Jul 25 01:29:46: Connection to vendor not found Jul 25 01:29:46: No connection from vendor Jul 25 01:29:46: Accounting response Jul 25 01:29:46: ...Done Accounting/Stop/answer/VoIP in 0.016734 seconds, 0.008586 spent in SQL queries. --REQUEST REQUEST-- Jul 25 01:29:46: Processing request (BE ver1.245.2.11,pid63599): NAS-IP-Address = '91.121.151.58' User-Name = '94.23.225.212' Called-Station-Id = '41215500327' Calling-Station-Id = '41215500329' Acct-Status-Type = 'Stop' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '08:29:39 GMT Mon Jul 25 2011' h323-connect-time = '08:29:43 GMT Mon Jul 25 2011' h323-disconnect-time = '08:29:45 GMT Mon Jul 25 2011' h323-disconnect-cause = '10' h323-conf-id = '165DB681 59729372 12D0EAA7 3FB42ACF' call-id = '91.121.151.58-1311582579.90' Acct-Session-Time = '2' session-protocol = 'sipv2' h323-remote-address = '94.23.225.212' Exec-Program-Log = 'porta-billing.pl' Jul 25 01:29:46: h323-conf-id=165DB681 59729372 12D0EAA7 3FB42ACF/1, call-id=91.121.151.58-1311582579.90/1 Jul 25 01:29:46: Found a call in cache with such id Jul 25 01:29:46: Replacing username '94.23.225.212' with the real username '41215500329' Jul 25 01:29:46: Copied account: 41215500329[58048,credit,balance=343.69000,limit=none] of customer Swiss offices[16165,balance=1536.94000,limit=2220.00000] from '94.23.225.212' into the current request Jul 25 01:29:46: PrepareNexecute 'GetActiveLegIdByAcct' Jul 25 01:29:46: SQL query 'GetActiveLegIdByAcct' executed in 0.001188 seconds Jul 25 01:29:46: PrepareNexecute 'DeleteActiveLeg' Jul 25 01:29:46: SQL query 'DeleteActiveLeg' executed in 0.00079 seconds Jul 25 01:29:46: End of call on incoming call leg from access NAS Jul 25 01:29:46: There have been authentication requests from more than one NAS Jul 25 01:29:46: No logged in accounts, call lifetime reduced to 15 Jul 25 01:29:46: Set lifetime with 15s to Mon Jul 25 01:30:01 2011 Jul 25 01:29:46: Looking up vendor/connection Jul 25 01:29:46: Trying to match connection for call Jul 25 01:29:46: Looking for a connection VoIP/answer Jul 25 01:29:46: VoIP, matching by the node IP '91.121.151.58' and User-Name '94.23.225.212' Jul 25 01:29:46: No VoIP from vendor connections were found Jul 25 01:29:46: Connection to vendor not found Jul 25 01:29:46: No connection from vendor Jul 25 01:29:46: Accounting response Jul 25 01:29:46: ...Done Accounting/Stop/answer/VoIP in 0.008397 seconds, 0.001978 spent in SQL queries. --REQUEST CALL-- Jul 25 01:30:10: Removing call 165DB681 59729372 12D0EAA7 3FB42ACF/1 Jul 25 01:30:10: Scheduling 41215500329 for logout, call lifetime reduced to 15 Jul 25 01:30:10: PrepareNexecute 'GetSessions' Jul 25 01:30:10: SQL query 'GetSessions' executed in 0.000561 seconds Jul 25 01:30:10: Logging out account '41215500329'(58048) from '165DB681 59729372 12D0EAA7 3FB42ACF' Jul 25 01:30:10: PrepareNexecute 'RemoveSession' Jul 25 01:30:10: SQL query 'RemoveSession' executed in 0.00043 seconds Jul 25 01:30:10: Cleaning up the call Jul 25 01:30:10: Usernames in all accounting requests are ok Jul 25 01:30:10: Processing answer/VoIP call leg Jul 25 01:30:10: Processing answer/VoIP call leg Jul 25 01:30:10: Skipping Start accounting Jul 25 01:30:10: Processing originate/VoIP call leg Jul 25 01:30:10: Charging call ... Jul 25 01:30:10: Zero duration call Jul 25 01:30:10: Using peak rate, since no off-peak is defined Jul 25 01:30:10: Can reuse the already initialized charge. Jul 25 01:30:10: Calculating account's charge by tariff 'business' Jul 25 01:30:10: Call to '41215500327' with duration 0 seconds will be charged for 0 seconds and cost is 0 (0s<1s) by rate 3429881 using 40084 as seed Jul 25 01:30:10: Reusing existing vendor charge Jul 25 01:30:10: Updating account usage of '41215500329' with 'Mon Jul 25 01:30:10 2011' Jul 25 01:30:10: PrepareNexecute 'UpdateAccountUsage' Jul 25 01:30:10: SQL query 'UpdateAccountUsage' executed in 0.000901 seconds Jul 25 01:30:10: Found call leg with connection, increasing setup time Jul 25 01:30:10: Processing originate/VoIP call leg Jul 25 01:30:10: Processing originate/VoIP call leg Jul 25 01:30:10: Skipping Start accounting Jul 25 01:30:10: Processing originate/VoIP call leg Jul 25 01:30:10: Processing answer/VoIP call leg Jul 25 01:30:10: Skipping Start accounting Jul 25 01:30:10: Processing answer/VoIP call leg Jul 25 01:30:10: Processing originate/VoIP call leg Jul 25 01:30:10: Skipping Start accounting Jul 25 01:30:10: Processing originate/VoIP call leg Jul 25 01:30:10: Charging call ... Jul 25 01:30:10: Zero duration call Jul 25 01:30:10: Using peak rate, since no off-peak is defined Jul 25 01:30:10: Can reuse the already initialized charge. Jul 25 01:30:10: Calculating account's charge by tariff 'business' Jul 25 01:30:10: Unable to compute call cost: No rates found for number 'unknown' in tariff 156 'business' Jul 25 01:30:10: Reusing existing vendor charge Jul 25 01:30:10: Updating account usage of '41215500329' with 'Mon Jul 25 01:30:10 2011' Jul 25 01:30:10: PrepareNexecute 'UpdateAccountUsage' Jul 25 01:30:10: SQL query 'UpdateAccountUsage' executed in 0.000445 seconds Jul 25 01:30:10: Found call leg with connection, increasing setup time Jul 25 01:30:10: There are no unsaved CDRs for this call left Jul 25 01:30:10: Call '165DB681 59729372 12D0EAA7 3FB42ACF/1' deleted from the cache Jul 25 01:30:10: Call 165DB681 59729372 12D0EAA7 3FB42ACF/1 removed --CALL