Current-time: Dec 30 00:39:57 PST (UTC -0800) H323-conf-id: 320AE3EC 70ABD407 17C1FAB3 25A470B9 SIP Call-ID: 91.121.122.64-1325234367.325 Requests: 5 REQUEST-- Dec 30 00:39:27: Processing request (BE ver1.245.2.11,pid20219): NAS-IP-Address = '91.121.122.64' NAS-Port-Name = 'SIP/412X55XXXXX-00000145' User-Name = '412X55XXXXX' Called-Station-Id = '02Y55YYYYY' Calling-Station-Id = '412X55XXXXX' h323-conf-id = '320AE3EC 70ABD407 17C1FAB3 25A470B9' call-id = '91.121.122.64-1325234367.325' Digest-Attributes = 'User-Name = "412X55XXXXX"' Digest-Attributes = 'Realm = "switzernet"' Digest-Attributes = 'Nonce = "52d57843"' Digest-Attributes = 'URI = "sip:02Y55YYYYY@astrad.switzernet.com"' Digest-Attributes = 'Method = "INVITE"' Digest-Attributes = 'Algorithm = "MD5"' Digest-Response = '3b7d2c46d582c7ed453b7d06a0b3ac3e' h323-remote-address = '212.147.8.99' h323-ivr-out = 'PortaBilling_Routing:SIP' h323-session-protocol = 'sipv2' h323-ivr-out = 'PortaBilling_AuthMethod:INVITE' Dec 30 00:39:27: h323-conf-id=320AE3EC 70ABD407 17C1FAB3 25A470B9/1, call-id=91.121.122.64-1325234367.325/1 Dec 30 00:39:27: H323/SIP call, use h323-conf-id, but remember call-id Dec 30 00:39:27: Checking if this call comes through a VoIP from vendor connection Dec 30 00:39:27: No VoIP from vendor connections were found Dec 30 00:39:27: PrepareNexecute 'AccountAuth' Dec 30 00:39:27: SQL query 'AccountAuth' executed in 0.002308 seconds Dec 30 00:39:27: Found Account: 412X55XXXXX[71344,credit,balance=0.20000,limit=none] of customer Swiss office test[30815,balance=0.20000,limit=11.00000] Dec 30 00:39:27: PrepareNexecute 'GetSessions' Dec 30 00:39:27: SQL query 'GetSessions' executed in 0.00055 seconds Dec 30 00:39:27: Account 412X55XXXXX is not logged in yet Dec 30 00:39:27: Verification of password using method 'digest_response': success Dec 30 00:39:27: PrepareNexecute 'GetAttributeValues' Dec 30 00:39:27: SQL query 'GetAttributeValues' executed in 0.000263 seconds Dec 30 00:39:27: PrepareNexecute 'GetCustomerActiveCalls' Dec 30 00:39:27: SQL query 'GetCustomerActiveCalls' executed in 0.000852 seconds Dec 30 00:39:27: PrepareNexecute 'GetAttributeValues' Dec 30 00:39:27: SQL query 'GetAttributeValues' executed in 0.000265 seconds Dec 30 00:39:27: Applying 'clir' service check translation rule on CLD ... Dec 30 00:39:27: Translation 's/^\*81/Y/; # hide=*81' applied: '02Y55YYYYY' unchanged Dec 30 00:39:27: Applying customer dialing translation rule on CLD ... Dec 30 00:39:27: Translation 'local_to_e164($_,{cc=>'41',dp=>'0',ip=>'00'});#% cc=41 dp=0 ip=00' applied: '02Y55YYYYY' -> '412Y55YYYYY' Dec 30 00:39:27: PrepareNexecute 'AccountAuth' Dec 30 00:39:27: SQL query 'AccountAuth' executed in 0.00243 seconds Dec 30 00:39:27: CLD '412Y55YYYYY' matching our account Dec 30 00:39:27: Setting up a new charge with tariff 'private' ... Dec 30 00:39:27: Using peak rate, since no off-peak is defined Dec 30 00:39:27: PrepareNexecute 'GetPricePerDestination*' Dec 30 00:39:27: SQL query 'GetPricePerDestination*' executed in 0.001705 seconds Dec 30 00:39:27: Compute maximum call duration for leg Account 412X55XXXXX to destination with funds 10.8 (customer funds 10.8) Dec 30 00:39:27: Maximum call duration: unlimited announced as unlimited (-1s...) by rate 3429839 using 50216 as seed Dec 30 00:39:27: Applying 'clir' service check translation rule on CLD ... Dec 30 00:39:27: Translation 's/^\*81/Y/; # hide=*81' applied: '02Y55YYYYY' unchanged Dec 30 00:39:27: Local termination 'PortaSIP': Checking follow-me for 412Y55YYYYY ... Dec 30 00:39:27: PrepareNexecute 'GetAccountFollowMe' Dec 30 00:39:27: SQL query 'GetAccountFollowMe' executed in 0.000405 seconds Dec 30 00:39:27: PrepareNexecute 'GetAccountFollowMeNumbers' Dec 30 00:39:27: SQL query 'GetAccountFollowMeNumbers' executed in 0.000212 seconds Dec 30 00:39:27: Checked 2011-12-30 09:39:27 Europe/Berlin against 'always': 1 Dec 30 00:39:27: Applying customer dialing translation rule on CLD ... Dec 30 00:39:27: Translation 'local_to_e164($_,{cc=>'41',dp=>'0',ip=>'00'});#% cc=41 dp=0 ip=00' applied: '41215502796' unchanged Dec 30 00:39:27: PrepareNexecute 'AccountAuth' Dec 30 00:39:27: SQL query 'AccountAuth' executed in 0.001868 seconds Dec 30 00:39:27: CLD '41215502796' matching our account Dec 30 00:39:27: Setting up a new charge with tariff 'business' ... Dec 30 00:39:27: Using peak rate, since no off-peak is defined Dec 30 00:39:27: PrepareNexecute 'GetPricePerDestination*' Dec 30 00:39:27: SQL query 'GetPricePerDestination*' executed in 0.0021 seconds Dec 30 00:39:27: Compute maximum call duration for leg Account 412Y55YYYYY to destination with funds 395.78 (customer funds 395.78) Dec 30 00:39:27: Maximum call duration: unlimited announced as unlimited (-1s...) by rate 3429881 using 88748 as seed Dec 30 00:39:27: Follow-me: Max recursion depth (1) reached Dec 30 00:39:27: Local termination 'PortaSIP': ... empty follow-me result list! Dec 30 00:39:27: PrepareNexecute 'GetSipServerAddress' Dec 30 00:39:27: SQL query 'GetSipServerAddress' executed in 0.000915 seconds Dec 30 00:39:27: CLD '412Y55YYYYY' found registered on 91.121.122.64. Dec 30 00:39:27: Use RTP Proxy according to policy 'Undetermined' => 'On Nat': Calling party NOT behind NAT, called party behind NAT Dec 30 00:39:27: PrepareNexecute 'GetSipServerAddress' Dec 30 00:39:27: SQL query 'GetSipServerAddress' executed in 0.000788 seconds Dec 30 00:39:27: CLD '41215502796' found registered on 91.121.143.56. Dec 30 00:39:27: Use RTP Proxy according to policy 'Undetermined' => 'On Nat': Calling party NOT behind NAT, called party behind NAT Dec 30 00:39:27: Logging in account '412X55XXXXX'(71344) to '320AE3EC 70ABD407 17C1FAB3 25A470B9' Dec 30 00:39:27: PrepareNexecute 'AddSession' Dec 30 00:39:27: SQL query 'AddSession' executed in 0.001791 seconds Dec 30 00:39:27: Authentication acknowledge response h323-ivr-in = PortaBilling_Routing:@;g-hunt=seq;credit-time=-1;rtpp=3;moh=1;patience=20 h323-ivr-in = PortaBilling_Routing: 412Y55YYYYY@91.121.122.64;expires=30;forward-on-fail=yes h323-ivr-in = PortaBilling_Routing: 41215502796@91.121.143.56;expires=15;bill-to=412Y55YYYYY;auth-cld=41215502796;access-code=FOLLOWME h323-billing-model = 0 h323-ivr-in = Tariff:private h323-ivr-in = PortaBilling_CLI:412X55XXXXX h323-ivr-in = MOH:1 h323-ivr-in = PortaBilling_Account:YES h323-ivr-in = PortaBilling_CompleteNumber:412Y55YYYYY h323-ivr-in = PortaBilling_Auth_CLD:412Y55YYYYY h323-ivr-in = PortaBilling_Auth_Reseller_CLD:412Y55YYYYY h323-return-code = 13 h323-currency = CHF h323-preferred-lang = fr Dec 30 00:39:27: ...Done Authorize/INVITE in 0.057163 seconds, 0.016452 spent in SQL queries. --REQUEST REQUEST-- Dec 30 00:39:29: Processing request (BE ver1.245.2.11,pid20219): NAS-IP-Address = '91.121.122.64' User-Name = '412X55XXXXX' Called-Station-Id = '412Y55YYYYY' Calling-Station-Id = '412X55XXXXX' Acct-Status-Type = 'Start' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '08:39:27 GMT Fri Dec 30 2011' h323-connect-time = '08:39:28 GMT Fri Dec 30 2011' h323-conf-id = '320AE3EC 70ABD407 17C1FAB3 25A470B9' call-id = '91.121.122.64-1325234367.325' Acct-Session-Id = '91.121.122.64-1325234367.325' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' NAS-Port = '5060' h323-ivr-out = 'PortaBilling_Auth_CLD:412Y55YYYYY' h323-ivr-out = 'DURATION:7200' h323-remote-address = 'sip-ua' Exec-Program-Log = 'porta-billing.pl' Dec 30 00:39:29: h323-conf-id=320AE3EC 70ABD407 17C1FAB3 25A470B9/1, call-id=91.121.122.64-1325234367.325/1 Dec 30 00:39:29: Found a call in cache with such id Dec 30 00:39:29: Copied account: 412X55XXXXX[71344,credit,balance=0.20000,limit=none] of customer Swiss office test[30815,balance=0.20000,limit=11.00000] from '91.121.122.64' into the current request Dec 30 00:39:29: Fixing time with duration 0 seconds from connect time Dec 30 00:39:29: PrepareNexecute 'GetActiveLegIdByAcct' Dec 30 00:39:29: SQL query 'GetActiveLegIdByAcct' executed in 0.001894 seconds Dec 30 00:39:29: Looking up vendor/connection Dec 30 00:39:29: Trying to match connection for call Dec 30 00:39:29: Looking for a connection VoIP/originate Dec 30 00:39:29: Outgoing VoIP, matching by the remote IP address 'SIP-UA' (env 1) Dec 30 00:39:29: Found connection 154 'SIP UA <-> SIP UA' to vendor 'Switzernet' Dec 30 00:39:29: Found vendor/connection Dec 30 00:39:29: PrepareNexecute 'InsertActiveLeg' Dec 30 00:39:29: SQL query 'InsertActiveLeg' executed in 0.001006 seconds Dec 30 00:39:29: Accounting response Dec 30 00:39:29: ...Done Accounting/Start/originate/VoIP in 0.011851 seconds, 0.002900 spent in SQL queries. --REQUEST REQUEST-- Dec 30 00:39:30: Processing request (BE ver1.245.2.11,pid20219): NAS-IP-Address = '91.121.122.64' User-Name = '412X55XXXXX' Called-Station-Id = '02Y55YYYYY' Calling-Station-Id = '412X55XXXXX' Acct-Status-Type = 'Start' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '08:39:27 GMT Fri Dec 30 2011' h323-connect-time = '08:39:30 GMT Fri Dec 30 2011' h323-conf-id = '320AE3EC 70ABD407 17C1FAB3 25A470B9' call-id = '91.121.122.64-1325234367.325' Acct-Session-Id = '91.121.122.64-1325234367.325' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' NAS-Port = '5060' alert-timepoint = '08:39:30 GMT Fri Dec 30 2011' h323-remote-address = '212.147.8.99' Exec-Program-Log = 'porta-billing.pl' Dec 30 00:39:30: h323-conf-id=320AE3EC 70ABD407 17C1FAB3 25A470B9/1, call-id=91.121.122.64-1325234367.325/1 Dec 30 00:39:30: Found a call in cache with such id Dec 30 00:39:30: Copied account: 412X55XXXXX[71344,credit,balance=0.20000,limit=none] of customer Swiss office test[30815,balance=0.20000,limit=11.00000] from '91.121.122.64' into the current request Dec 30 00:39:30: Fixing time with duration 0 seconds from connect time Dec 30 00:39:30: PrepareNexecute 'GetActiveLegIdByAcct' Dec 30 00:39:30: SQL query 'GetActiveLegIdByAcct' executed in 0.001201 seconds Dec 30 00:39:30: Looking up vendor/connection Dec 30 00:39:30: Trying to match connection for call Dec 30 00:39:30: Looking for a connection VoIP/answer Dec 30 00:39:30: VoIP, matching by the node IP '91.121.122.64' and User-Name '412X55XXXXX' Dec 30 00:39:30: No VoIP from vendor connections were found Dec 30 00:39:30: Connection to vendor not found Dec 30 00:39:30: PrepareNexecute 'InsertActiveLeg' Dec 30 00:39:30: SQL query 'InsertActiveLeg' executed in 0.001144 seconds Dec 30 00:39:30: Accounting response Dec 30 00:39:30: ...Done Accounting/Start/answer/VoIP in 0.010786 seconds, 0.002345 spent in SQL queries. --REQUEST REQUEST-- Dec 30 00:39:35: Processing request (BE ver1.245.2.11,pid20219): NAS-IP-Address = '91.121.122.64' User-Name = '412X55XXXXX' Called-Station-Id = '412Y55YYYYY' Calling-Station-Id = '412X55XXXXX' Acct-Status-Type = 'Stop' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '08:39:27 GMT Fri Dec 30 2011' h323-connect-time = '08:39:28 GMT Fri Dec 30 2011' h323-disconnect-time = '08:39:34 GMT Fri Dec 30 2011' h323-disconnect-cause = '10' h323-conf-id = '320AE3EC 70ABD407 17C1FAB3 25A470B9' call-id = '91.121.122.64-1325234367.325' Acct-Session-Id = '91.121.122.64-1325234367.325' Acct-Session-Time = '4' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' NAS-Port = '5060' h323-ivr-out = 'PortaBilling_Auth_CLD:412Y55YYYYY' h323-ivr-out = 'DURATION:7200' h323-remote-address = 'sip-ua' Exec-Program-Log = 'porta-billing.pl' Dec 30 00:39:35: h323-conf-id=320AE3EC 70ABD407 17C1FAB3 25A470B9/1, call-id=91.121.122.64-1325234367.325/1 Dec 30 00:39:35: Found a call in cache with such id Dec 30 00:39:35: Copied account: 412X55XXXXX[71344,credit,balance=0.20000,limit=none] of customer Swiss office test[30815,balance=0.20000,limit=11.00000] from '91.121.122.64' into the current request Dec 30 00:39:35: PrepareNexecute 'GetActiveLegIdByAcct' Dec 30 00:39:35: SQL query 'GetActiveLegIdByAcct' executed in 0.001373 seconds Dec 30 00:39:35: PrepareNexecute 'DeleteActiveLeg' Dec 30 00:39:35: SQL query 'DeleteActiveLeg' executed in 0.000904 seconds Dec 30 00:39:35: End of the outgoing call for logged in account. Waiting another outgoing call or hang up Dec 30 00:39:35: Set lifetime with 15s to Fri Dec 30 00:39:50 2011 Dec 30 00:39:35: Looking up vendor/connection Dec 30 00:39:35: Trying to match connection for call Dec 30 00:39:35: Looking for a connection VoIP/originate Dec 30 00:39:35: Outgoing VoIP, matching by the remote IP address 'SIP-UA' (env 1) Dec 30 00:39:35: Found connection 154 'SIP UA <-> SIP UA' to vendor 'Switzernet' Dec 30 00:39:35: Found vendor/connection Dec 30 00:39:35: Applying connection translation rule on CLD ... Dec 30 00:39:35: Translation 's/^00//; s/^0/41/;' applied: '412Y55YYYYY' unchanged Dec 30 00:39:35: Charging call ... Dec 30 00:39:35: Using peak rate, since no off-peak is defined Dec 30 00:39:35: Can reuse the already initialized charge. Dec 30 00:39:35: Calculating account's charge by tariff 'private' Dec 30 00:39:35: Call to '412Y55YYYYY' with duration 6 seconds will be charged for 6 seconds and cost is 0 (1x1x0+5x1x0) by rate 3429839 using 50216 as seed Dec 30 00:39:35: Setting up a new charge with tariff 'SIP Termination' ... Dec 30 00:39:35: Using peak rate, since no off-peak is defined Dec 30 00:39:35: PrepareNexecute 'GetPricePerDestination*' Dec 30 00:39:35: SQL query 'GetPricePerDestination*' executed in 0.001718 seconds Dec 30 00:39:35: Calculating vendor's charge by tariff 'SIP Termination' Dec 30 00:39:35: Call to '412Y55YYYYY' with duration 6 seconds will be charged for 6 seconds and cost is 0 (1x1x0+5x1x0) by rate 2144843 using 50216 as seed Dec 30 00:39:35: Charging account for the call Dec 30 00:39:35: Inserting CDR Dec 30 00:39:35: PrepareNexecute 'InsertAccountCDR' Dec 30 00:39:35: SQL query 'InsertAccountCDR' executed in 0.002068 seconds Dec 30 00:39:35: Charging account's owner for the call Dec 30 00:39:35: Charging vendor for the call Dec 30 00:39:35: Charging vendor 32 'Switzernet' 0 Dec 30 00:39:35: Inserting CDR Dec 30 00:39:35: PrepareNexecute 'InsertVendorCDR' Dec 30 00:39:35: SQL query 'InsertVendorCDR' executed in 0.001079 seconds Dec 30 00:39:35: PrepareNexecute 'UpdateVendorBalance' Dec 30 00:39:35: SQL query 'UpdateVendorBalance' executed in 0.000412 seconds Dec 30 00:39:35: Accounting response Dec 30 00:39:35: ...Done Accounting/Stop/originate/VoIP in 0.024309 seconds, 0.007554 spent in SQL queries. --REQUEST REQUEST-- Dec 30 00:39:35: Processing request (BE ver1.245.2.11,pid20219): NAS-IP-Address = '91.121.122.64' User-Name = '412X55XXXXX' Called-Station-Id = '02Y55YYYYY' Calling-Station-Id = '412X55XXXXX' Acct-Status-Type = 'Stop' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '08:39:27 GMT Fri Dec 30 2011' h323-connect-time = '08:39:30 GMT Fri Dec 30 2011' h323-disconnect-time = '08:39:34 GMT Fri Dec 30 2011' h323-disconnect-cause = '10' h323-conf-id = '320AE3EC 70ABD407 17C1FAB3 25A470B9' call-id = '91.121.122.64-1325234367.325' Acct-Session-Id = '91.121.122.64-1325234367.325' Acct-Session-Time = '4' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' NAS-Port = '5060' h323-ivr-out = 'PortaBilling_Session:unlock' alert-timepoint = '08:39:30 GMT Fri Dec 30 2011' h323-remote-address = '212.147.8.99' Exec-Program-Log = 'porta-billing.pl' Dec 30 00:39:35: h323-conf-id=320AE3EC 70ABD407 17C1FAB3 25A470B9/1, call-id=91.121.122.64-1325234367.325/1 Dec 30 00:39:35: Found a call in cache with such id Dec 30 00:39:35: Copied account: 412X55XXXXX[71344,credit,balance=0.20000,limit=none] of customer Swiss office test[30815,balance=0.20000,limit=11.00000] from '91.121.122.64' into the current request Dec 30 00:39:35: PrepareNexecute 'GetActiveLegIdByAcct' Dec 30 00:39:35: SQL query 'GetActiveLegIdByAcct' executed in 0.000959 seconds Dec 30 00:39:35: PrepareNexecute 'DeleteActiveLeg' Dec 30 00:39:35: SQL query 'DeleteActiveLeg' executed in 0.000809 seconds Dec 30 00:39:35: Force unlock requested by NAS Dec 30 00:39:35: Scheduling 412X55XXXXX for logout, call lifetime reduced to 15 Dec 30 00:39:35: PrepareNexecute 'GetSessions' Dec 30 00:39:35: SQL query 'GetSessions' executed in 0.001627 seconds Dec 30 00:39:35: Logging out account '412X55XXXXX'(71344) from '320AE3EC 70ABD407 17C1FAB3 25A470B9' Dec 30 00:39:35: PrepareNexecute 'RemoveSession' Dec 30 00:39:35: SQL query 'RemoveSession' executed in 0.001011 seconds Dec 30 00:39:35: Set lifetime with 15s to Fri Dec 30 00:39:50 2011 Dec 30 00:39:35: Looking up vendor/connection Dec 30 00:39:35: Trying to match connection for call Dec 30 00:39:35: Looking for a connection VoIP/answer Dec 30 00:39:35: VoIP, matching by the node IP '91.121.122.64' and User-Name '412X55XXXXX' Dec 30 00:39:35: No VoIP from vendor connections were found Dec 30 00:39:35: Connection to vendor not found Dec 30 00:39:35: No connection from vendor Dec 30 00:39:35: Accounting response Dec 30 00:39:35: ...Done Accounting/Stop/answer/VoIP in 0.016288 seconds, 0.004406 spent in SQL queries. --REQUEST