Current-time: Jan 29 12:34:17 PST (UTC -0800) H323-conf-id: 6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A SIP Call-ID: 3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212 SIP Call-ID: 94.23.225.212-1264796943.26 SIP Call-ID: 94.23.242.200-1264796943.138 Requests: 10 REQUEST-- Jan 29 12:29:03: Processing request (BE ver1.245.2.11,pid15598): NAS-IP-Address = '94.23.225.212' NAS-Port-Name = 'SIP/94.23.242.200-6a880d00' User-Name = '94.23.242.200' Called-Station-Id = '41216912818' Calling-Station-Id = '41215500329' h323-conf-id = '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A' call-id = '94.23.225.212-1264796943.26' Password = 'xxxxxxxxxx' h323-ivr-out = 'PortaBilling_Routing:SIP' Jan 29 12:29:03: h323-conf-id=6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1, call-id=94.23.225.212-1264796943.26/1 Jan 29 12:29:03: H323/SIP call, use h323-conf-id, but remember call-id Jan 29 12:29:03: Authorization of the trusted node Jan 29 12:29:03: IP based authorization, force 'plaintext' password verification Jan 29 12:29:03: Verification of password using method 'plaintext': success Jan 29 12:29:03: '94.23.242.200' 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 12:29:03: PrepareNexecute 'AccountAuth' Jan 29 12:29:03: SQL query 'AccountAuth' executed in 0.001448 seconds Jan 29 12:29:03: CLD '41216912818' is an off-net number Jan 29 12:29:03: Remote termination 'PortaSIP': Calculating routing for 41216912818 Jan 29 12:29:03: Falling back to default routing since no routing plan information is available Jan 29 12:29:03: RTP Proxy with origination preference '', Calling party NOT behind NAT. Jan 29 12:29:03: Looking up routes to '41216912818' using '' routing plan Jan 29 12:29:03: PrepareNexecute 'GetRoutingPerDestination*' Jan 29 12:29:03: SQL query 'GetRoutingPerDestination*' executed in 0.006611 seconds Jan 29 12:29:03: Checked 2010-01-29 21:29:03 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 12:29:03: Start of call is peak level 1 Jan 29 12:29:03: Using peak rate, since no off-peak is defined Jan 29 12:29:03: Checked 2010-01-29 21:29:03 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 12:29:03: Start of call is peak level 1 Jan 29 12:29:03: Checked 2010-01-29 21:29:03 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 12:29:03: Start of call is peak level 1 Jan 29 12:29:03: Using peak rate, since no off-peak is defined Jan 29 12:29:03: Using peak rate, since no off-peak is defined Jan 29 12:29:03: Using peak rate, since no off-peak is defined Jan 29 12:29:03: Checked 2010-01-29 21:29:03 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 12:29:03: Start of call is peak level 1 Jan 29 12:29:03: Using peak rate, since no off-peak is defined Jan 29 12:29:03: Applying route outgoing CLD translation on '41216912818' ... Jan 29 12:29:03: Translation 's/^(\d)/\+$1/;' applied: '41216912818' -> '+41216912818' Jan 29 12:29:03: Applying route outgoing CLD translation on '41216912818' ... Jan 29 12:29:03: Translation 's/^(\d)/\+$1/;' applied: '41216912818' -> '+41216912818' Jan 29 12:29:03: Applying route outgoing CLD translation on '41216912818' ... Jan 29 12:29:03: Translation 's/^(\d)/00$1/;' applied: '41216912818' -> '0041216912818' Jan 29 12:29:03: Applying route outgoing CLD translation on '41216912818' ... Jan 29 12:29:03: Translation 's/^(\d)/\+$1/' applied: '41216912818' -> '+41216912818' Jan 29 12:29:03: Applying route outgoing CLI translation on '41215500329' ... Jan 29 12:29:03: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 12:29:03: Applying route outgoing CLI translation on '41215500329' ... Jan 29 12:29:03: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 12:29:03: Applying route outgoing CLI translation on '41215500329' ... Jan 29 12:29:03: Translation 's/^(\d)/00$1/;' applied: '41215500329' -> '0041215500329' Jan 29 12:29:03: Applying route outgoing CLI translation on '41215500329' ... Jan 29 12:29:03: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 12:29:03: Result routes to destination '41216912818': +41216912818@212.249.15.3, prio = 10, cost = 0.00654, off-peak, 'OpenSER 3' - to remote GW +41216912818@212.249.15.9, prio = 10, cost = 0.00654, off-peak, 'OpenSER 9' - 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 12:29:03: 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.3 h323-ivr-in = PortaBilling_Routing: +41216912818@212.249.15.9 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 12:29:03: ...Done Authorize in 0.030374 seconds, 0.008059 spent in SQL queries. --REQUEST REQUEST-- Jan 29 12:29:04: 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 = '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A' call-id = '3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212' Password = 'cisco' 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:3138847566' NAS-Port = '5060' Jan 29 12:29:04: h323-conf-id=6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1, call-id=3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212/1 Jan 29 12:29:04: H323/SIP call, use h323-conf-id, but remember call-id Jan 29 12:29:04: Authorization of the trusted node Jan 29 12:29:04: IP based authorization, force 'plaintext' password verification Jan 29 12:29:04: Verification of password using method 'plaintext': success Jan 29 12:29:04: '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 12:29:04: PrepareNexecute 'AccountAuth' Jan 29 12:29:04: SQL query 'AccountAuth' executed in 0.002703 seconds Jan 29 12:29:04: CLD '41216912818' is an off-net number Jan 29 12:29:04: Remote termination 'PortaSIP': Calculating routing for 41216912818 Jan 29 12:29:04: Falling back to default routing since no routing plan information is available Jan 29 12:29:04: RTP Proxy with origination preference '', Calling party NOT behind NAT. Jan 29 12:29:04: Looking up routes to '41216912818' using '' routing plan Jan 29 12:29:04: PrepareNexecute 'GetRoutingPerDestination*' Jan 29 12:29:04: SQL query 'GetRoutingPerDestination*' executed in 0.006147 seconds Jan 29 12:29:04: Checked 2010-01-29 21:29:04 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 12:29:04: Start of call is peak level 1 Jan 29 12:29:04: Using peak rate, since no off-peak is defined Jan 29 12:29:04: Checked 2010-01-29 21:29:04 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 12:29:04: Start of call is peak level 1 Jan 29 12:29:04: Checked 2010-01-29 21:29:04 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 12:29:04: Start of call is peak level 1 Jan 29 12:29:04: Using peak rate, since no off-peak is defined Jan 29 12:29:04: Using peak rate, since no off-peak is defined Jan 29 12:29:04: Using peak rate, since no off-peak is defined Jan 29 12:29:04: Checked 2010-01-29 21:29:04 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 12:29:04: Start of call is peak level 1 Jan 29 12:29:04: Using peak rate, since no off-peak is defined Jan 29 12:29:04: Applying route outgoing CLD translation on '41216912818' ... Jan 29 12:29:04: Translation 's/^(\d)/\+$1/;' applied: '41216912818' -> '+41216912818' Jan 29 12:29:04: Applying route outgoing CLD translation on '41216912818' ... Jan 29 12:29:04: Translation 's/^(\d)/\+$1/;' applied: '41216912818' -> '+41216912818' Jan 29 12:29:04: Applying route outgoing CLD translation on '41216912818' ... Jan 29 12:29:04: Translation 's/^(\d)/00$1/;' applied: '41216912818' -> '0041216912818' Jan 29 12:29:04: Applying route outgoing CLD translation on '41216912818' ... Jan 29 12:29:04: Translation 's/^(\d)/\+$1/' applied: '41216912818' -> '+41216912818' Jan 29 12:29:04: Applying route outgoing CLI translation on '41215500329' ... Jan 29 12:29:04: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 12:29:04: Applying route outgoing CLI translation on '41215500329' ... Jan 29 12:29:04: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 12:29:04: Applying route outgoing CLI translation on '41215500329' ... Jan 29 12:29:04: Translation 's/^(\d)/00$1/;' applied: '41215500329' -> '0041215500329' Jan 29 12:29:04: Applying route outgoing CLI translation on '41215500329' ... Jan 29 12:29:04: Translation 's/^(\d)/\+$1/;' applied: '41215500329' -> '+41215500329' Jan 29 12:29:04: Result routes to destination '41216912818': +41216912818@212.249.15.3, prio = 10, cost = 0.00654, off-peak, 'OpenSER 3' - to remote GW +41216912818@212.249.15.9, prio = 10, cost = 0.00654, off-peak, 'OpenSER 9' - 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 12:29:04: 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.3 h323-ivr-in = PortaBilling_Routing: +41216912818@212.249.15.9 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 12:29:04: ...Done Authorize/INVITE in 0.030759 seconds, 0.008850 spent in SQL queries. --REQUEST REQUEST-- Jan 29 12:29: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' Acct-Status-Type = 'Start' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '20:29:04.252 GMT Fri Jan 29 2010' h323-connect-time = '20:29:12.665 GMT Fri Jan 29 2010' h323-conf-id = '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A' call-id = '3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212' Acct-Session-Id = '3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' h323-remote-address = '212.249.15.3' h323-ivr-out = 'DURATION:7200' h323-ivr-out = 'PortaBilling_Auth_CLD:41216912818' h323-ivr-out = 'PortaBilling_Seed:3138847566' alert-timepoint = '20:29:05.364 GMT Fri Jan 29 2010' NAS-Port = '5060' Exec-Program-Log = 'porta-billing.pl' Jan 29 12:29:12: h323-conf-id=6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1, call-id=3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212/1 Jan 29 12:29:12: H323/SIP call, use h323-conf-id, but remember call-id Jan 29 12:29:12: Fixing time with duration 0 seconds from connect time Jan 29 12:29:12: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 12:29:12: SQL query 'GetActiveLegIdByAcct' executed in 0.001867 seconds Jan 29 12:29: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 12:29:12: Looking up vendor/connection Jan 29 12:29:12: Trying to match connection for call Jan 29 12:29:12: Looking for a connection VoIP/originate Jan 29 12:29:12: Outgoing VoIP, matching by the remote IP address '212.249.15.3' (env 1) Jan 29 12:29:12: Found connection 205 'OpenSER 3' to vendor 'Verizon' Jan 29 12:29:12: Found vendor/connection Jan 29 12:29:12: PrepareNexecute 'InsertActiveLeg' Jan 29 12:29:12: SQL query 'InsertActiveLeg' executed in 0.000956 seconds Jan 29 12:29:12: Accounting response Jan 29 12:29:12: ...Done Accounting/Start/originate/VoIP in 0.009623 seconds, 0.002823 spent in SQL queries. --REQUEST REQUEST-- Jan 29 12:29: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' Acct-Status-Type = 'Start' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '20:29:04.148 GMT Fri Jan 29 2010' h323-connect-time = '20:29:12.667 GMT Fri Jan 29 2010' h323-conf-id = '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A' call-id = '3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212' Acct-Session-Id = '3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' h323-remote-address = '94.23.225.212' h323-ivr-out = 'PortaBilling_Seed:3138847566' alert-timepoint = '20:29:12.667 GMT Fri Jan 29 2010' NAS-Port = '5060' Exec-Program-Log = 'porta-billing.pl' Jan 29 12:29:12: h323-conf-id=6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1, call-id=3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212/1 Jan 29 12:29:12: Found a call in cache with such id Jan 29 12:29:12: Fixing time with duration 0 seconds from connect time Jan 29 12:29:12: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 12:29:12: SQL query 'GetActiveLegIdByAcct' executed in 0.001867 seconds Jan 29 12:29: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 12:29:12: Looking up vendor/connection Jan 29 12:29:12: Trying to match connection for call Jan 29 12:29:12: Looking for a connection VoIP/answer Jan 29 12:29:12: VoIP, matching by the node IP '91.121.19.149' and User-Name '94.23.225.212' Jan 29 12:29:12: No VoIP from vendor connections were found Jan 29 12:29:12: Connection to vendor not found Jan 29 12:29:12: PrepareNexecute 'InsertActiveLeg' Jan 29 12:29:12: SQL query 'InsertActiveLeg' executed in 0.00096 seconds Jan 29 12:29:12: Accounting response Jan 29 12:29:12: ...Done Accounting/Start/answer/VoIP in 0.011511 seconds, 0.002827 spent in SQL queries. --REQUEST REQUEST-- Jan 29 12:30:56: 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 = '20:29:04.252 GMT Fri Jan 29 2010' h323-connect-time = '20:29:12.252 GMT Fri Jan 29 2010' h323-disconnect-time = '20:30:55.252 GMT Fri Jan 29 2010' h323-disconnect-cause = '0' h323-voice-quality = '0' h323-conf-id = '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A' call-id = '3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212' Acct-Session-Id = '3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212' Acct-Session-Time = '103' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' h323-remote-address = '212.249.15.3' h323-ivr-out = 'DURATION:7200' h323-ivr-out = 'PortaBilling_Auth_CLD:41216912818' h323-ivr-out = 'PortaBilling_Seed:3138847566' Acct-Terminate-Cause = 'User-Request' alert-timepoint = '20:29:05.364 GMT Fri Jan 29 2010' NAS-Port = '5060' Exec-Program-Log = 'porta-billing.pl' Jan 29 12:30:56: h323-conf-id=6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1, call-id=3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212/1 Jan 29 12:30:56: Found a call in cache with such id Jan 29 12:30:56: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 12:30:56: SQL query 'GetActiveLegIdByAcct' executed in 0.001519 seconds Jan 29 12:30:56: PrepareNexecute 'DeleteActiveLeg' Jan 29 12:30:56: SQL query 'DeleteActiveLeg' executed in 0.001198 seconds Jan 29 12:30:56: User-Name needs correction. Postponing. Jan 29 12:30:56: Accounting response Jan 29 12:30:56: ...Done Accounting/Stop/originate/VoIP in 0.009772 seconds, 0.002717 spent in SQL queries. --REQUEST REQUEST-- Jan 29 12:30:56: 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 = '20:29:04.148 GMT Fri Jan 29 2010' h323-connect-time = '20:29:12.148 GMT Fri Jan 29 2010' h323-disconnect-time = '20:30:55.148 GMT Fri Jan 29 2010' h323-disconnect-cause = '0' h323-voice-quality = '0' h323-conf-id = '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A' call-id = '3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212' Acct-Session-Id = '3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212' Acct-Session-Time = '103' Acct-Delay-Time = '0' h323-session-protocol = 'sipv2' h323-remote-address = '94.23.225.212' h323-ivr-out = 'PortaBilling_Seed:3138847566' Acct-Terminate-Cause = 'User-Request' h323-ivr-out = 'PortaBilling_Session:unlock' alert-timepoint = '20:29:12.667 GMT Fri Jan 29 2010' NAS-Port = '5060' Exec-Program-Log = 'porta-billing.pl' Jan 29 12:30:56: h323-conf-id=6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1, call-id=3fcb74c8719ad94928c33ca63f43ebc2@94.23.225.212/1 Jan 29 12:30:56: Found a call in cache with such id Jan 29 12:30:56: Copying randomization seed '3138847566' into request's PortaBilling_Seed attribute Jan 29 12:30:56: Copying originator authorized CLD '41216912818' into current request Jan 29 12:30:56: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 12:30:56: SQL query 'GetActiveLegIdByAcct' executed in 0.00214 seconds Jan 29 12:30:56: PrepareNexecute 'DeleteActiveLeg' Jan 29 12:30:56: SQL query 'DeleteActiveLeg' executed in 0.00127 seconds Jan 29 12:30:56: User-Name needs correction. Postponing. Jan 29 12:30:56: Accounting response Jan 29 12:30:56: ...Done Accounting/Stop/answer/VoIP in 0.009496 seconds, 0.003410 spent in SQL queries. --REQUEST CALL-- Jan 29 12:31:17: Removing call 6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1 Jan 29 12:31:17: No logged in accounts, call lifetime reduced to 15 Jan 29 12:31:17: Cleaning up the call Jan 29 12:31:17: No request from trusted node to recover username Jan 29 12:31:17: PrepareNexecute 'MailAlarm' Jan 29 12:31:17: SQL query 'MailAlarm' executed in 0.001438 seconds Jan 29 12:31:17: There are no recepients of mail alarms with type 'UNKN' Jan 29 12:31:17: Processing answer/VoIP call leg Jan 29 12:31:17: Skipping Start accounting Jan 29 12:31:17: Processing answer/VoIP call leg Jan 29 12:31:17: Found not billed accounting request with the duration more than zero - bill it now Jan 29 12:31:17: Looking up vendor/connection Jan 29 12:31:17: Trying to match connection for call Jan 29 12:31:17: Looking for a connection VoIP/answer Jan 29 12:31:17: VoIP, matching by the node IP '91.121.19.149' and User-Name '94.23.225.212' Jan 29 12:31:17: No VoIP from vendor connections were found Jan 29 12:31:17: Connection to vendor not found Jan 29 12:31:17: Charging call ... Jan 29 12:31:17: This is incoming call, bill only vendor Jan 29 12:31:17: Vendor is undefined (on-net call?), call is not billed Jan 29 12:31:17: Processing originate/VoIP call leg Jan 29 12:31:17: Skipping Start accounting Jan 29 12:31:17: Processing originate/VoIP call leg Jan 29 12:31:17: Found not billed accounting request with the duration more than zero - bill it now Jan 29 12:31:17: Looking up vendor/connection Jan 29 12:31:17: Trying to match connection for call Jan 29 12:31:17: Looking for a connection VoIP/originate Jan 29 12:31:17: Outgoing VoIP, matching by the remote IP address '212.249.15.3' (env 1) Jan 29 12:31:17: Found connection 205 'OpenSER 3' to vendor 'Verizon' Jan 29 12:31:17: Found vendor/connection Jan 29 12:31:17: Applying connection translation rule on CLD ... Jan 29 12:31:17: Translation 's/^\+//;' applied: '+41216912818' -> '41216912818' Jan 29 12:31:17: Charging call ... Jan 29 12:31:17: '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 12:31:17: Setting up a new charge with tariff 'verizon-PRE' ... Jan 29 12:31:17: Checked 2010-01-29 21:29: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 12:31:17: Checked 2010-01-29 21:30:55 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 12:31:17: Start of call is peak level 1 Jan 29 12:31:17: End of call is peak level 1 Jan 29 12:31:17: PrepareNexecute 'GetPricePerDestination*' Jan 29 12:31:17: SQL query 'GetPricePerDestination*' executed in 0.002221 seconds Jan 29 12:31:17: Calculating vendor's charge by tariff 'verizon-PRE' Jan 29 12:31:17: Call to '41216912818' with duration 103 seconds will be charged for 103 seconds and cost is 0.01625 (1x1x0.2709+102x1x0.0069) by rate 3530937 using -1156079098 as seed Jan 29 12:31:17: Attempt to charge call with unknown Account, Customer Jan 29 12:31:17: Charging vendor for the call Jan 29 12:31:17: Charging vendor 55 'Verizon' 0.01625 Jan 29 12:31:17: Inserting CDR Jan 29 12:31:17: PrepareNexecute 'InsertVendorCDR' Jan 29 12:31:17: SQL query 'InsertVendorCDR' executed in 0.001168 seconds Jan 29 12:31:17: PrepareNexecute 'UpdateVendorBalance' Jan 29 12:31:17: SQL query 'UpdateVendorBalance' executed in 0.000803 seconds Jan 29 12:31:17: There are no unsaved CDRs for this call left Jan 29 12:31:17: Call '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1' deleted from the cache Jan 29 12:31:17: Call 6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1 removed --CALL REQUEST-- Jan 29 12:31:56: 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 = '20:29:03 GMT Fri Jan 29 2010' h323-connect-time = '20:29:12 GMT Fri Jan 29 2010' h323-disconnect-time = '20:30:56 GMT Fri Jan 29 2010' h323-disconnect-cause = '10' h323-conf-id = '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A' call-id = '94.23.225.212-1264796943.26' Acct-Session-Time = '104' session-protocol = 'sipv2' h323-remote-address = '91.121.19.149' Exec-Program-Log = 'porta-billing.pl' Jan 29 12:31:56: h323-conf-id=6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1, call-id=94.23.225.212-1264796943.26/1 Jan 29 12:31:56: H323/SIP call, use h323-conf-id, but remember call-id Jan 29 12:31:56: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 12:31:56: SQL query 'GetActiveLegIdByAcct' executed in 0.001457 seconds Jan 29 12:31:56: User-Name needs correction. Postponing. Jan 29 12:31:56: Accounting response Jan 29 12:31:56: ...Done Accounting/Stop/originate/VoIP in 0.006641 seconds, 0.001457 spent in SQL queries. --REQUEST REQUEST-- Jan 29 12:31:56: 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 = 'Stop' h323-call-origin = 'originate' h323-call-type = 'VoIP' h323-setup-time = '20:29:03 GMT Fri Jan 29 2010' h323-connect-time = '20:29:12 GMT Fri Jan 29 2010' h323-disconnect-time = '20:30:56 GMT Fri Jan 29 2010' h323-disconnect-cause = '10' h323-conf-id = '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A' call-id = '94.23.242.200-1264796943.138' Acct-Session-Time = '104' session-protocol = 'sipv2' h323-remote-address = '94.23.225.212' Exec-Program-Log = 'porta-billing.pl' Jan 29 12:31:56: h323-conf-id=6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1, call-id=94.23.242.200-1264796943.138/1 Jan 29 12:31:56: Found a call in cache with such id Jan 29 12:31:56: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 12:31:56: SQL query 'GetActiveLegIdByAcct' executed in 0.001935 seconds Jan 29 12:31:56: PrepareNexecute 'AccountAccounting' Jan 29 12:31:56: SQL query 'AccountAccounting' executed in 0.001922 seconds Jan 29 12:31:56: Found Account: 41215500329[58048,credit,balance=0.29000,limit=none] of customer Swiss offices[16165,balance=633.57000,limit=700.00000] Jan 29 12:31:56: End of the outgoing call for account, which appears as never logged-in Jan 29 12:31:56: Set lifetime with 15s to Fri Jan 29 12:32:11 2010 Jan 29 12:31:56: Looking up vendor/connection Jan 29 12:31:56: Trying to match connection for call Jan 29 12:31:56: Looking for a connection VoIP/originate Jan 29 12:31:56: Outgoing VoIP, matching by the remote IP address '94.23.225.212' (env 1) Jan 29 12:31:56: Call goes to our trusted node astrad.switzernet.com, on net leg Jan 29 12:31:56: Connection to vendor not found Jan 29 12:31:56: No connection to vendor - on-net call leg Jan 29 12:31:56: Copying randomization seed '46207' into request's PortaBilling_Seed attribute Jan 29 12:31:56: Copied account: 41215500329[58048,credit,balance=0.29000,limit=none] of customer Swiss offices[16165,balance=633.57000,limit=700.00000] into cached request, early attemt to charge ... Jan 29 12:31:56: Looking up vendor/connection Jan 29 12:31:56: Trying to match connection for call Jan 29 12:31:56: Looking for a connection VoIP/originate Jan 29 12:31:56: Outgoing VoIP, matching by the remote IP address '91.121.19.149' (env 1) Jan 29 12:31:56: Call goes to our trusted node fr2.youroute.net, on net leg Jan 29 12:31:56: Connection to vendor not found Jan 29 12:31:56: Accounting response Jan 29 12:31:56: ...Done Accounting/Stop/originate/VoIP in 0.013646 seconds, 0.003857 spent in SQL queries. --REQUEST CALL-- Jan 29 12:32:20: Removing call 6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1 Jan 29 12:32:20: No logged in accounts, call lifetime reduced to 15 Jan 29 12:32:20: Cleaning up the call Jan 29 12:32:20: Usernames in all accounting requests are ok Jan 29 12:32:20: Processing originate/VoIP call leg Jan 29 12:32:20: Found not billed accounting request with the duration more than zero - bill it now Jan 29 12:32:20: Charging call ... Jan 29 12:32:20: Vendor is undefined (on-net call?), call is not billed Jan 29 12:32:20: Processing originate/VoIP call leg Jan 29 12:32:20: No outgoing connections to vendor, on-net call Jan 29 12:32:20: Updating account usage of '41215500329' with 'Fri Jan 29 12:32:20 2010' Jan 29 12:32:20: PrepareNexecute 'UpdateAccountUsage' Jan 29 12:32:20: SQL query 'UpdateAccountUsage' executed in 0.001188 seconds Jan 29 12:32:20: Inserting on-net CDR for this call Jan 29 12:32:20: Inserting CDR Jan 29 12:32:20: PrepareNexecute 'InsertOnNetCDR' Jan 29 12:32:20: SQL query 'InsertOnNetCDR' executed in 0.001547 seconds Jan 29 12:32:20: PrepareNexecute 'GetEnvMail' Jan 29 12:32:20: SQL query 'GetEnvMail' executed in 0.000299 seconds Jan 29 12:32:20: PrepareNexecute 'MailAlarm' Jan 29 12:32:20: SQL query 'MailAlarm' executed in 0.000281 seconds Jan 29 12:32:20: There are no recepients of mail alarms with type 'MIS_GENERAL' Jan 29 12:32:20: Call '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1' deleted from the cache Jan 29 12:32:20: Call 6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1 removed --CALL REQUEST-- Jan 29 12:32:56: 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 = '20:29:03 GMT Fri Jan 29 2010' h323-connect-time = '20:29:12 GMT Fri Jan 29 2010' h323-disconnect-time = '20:30:56 GMT Fri Jan 29 2010' h323-disconnect-cause = '10' h323-conf-id = '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A' call-id = '94.23.225.212-1264796943.26' Acct-Session-Time = '104' session-protocol = 'sipv2' h323-remote-address = '94.23.242.200' Exec-Program-Log = 'porta-billing.pl' Jan 29 12:32:56: h323-conf-id=6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1, call-id=94.23.225.212-1264796943.26/1 Jan 29 12:32:56: H323/SIP call, use h323-conf-id, but remember call-id Jan 29 12:32:56: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 12:32:56: SQL query 'GetActiveLegIdByAcct' executed in 0.002577 seconds Jan 29 12:32:56: User-Name needs correction. Postponing. Jan 29 12:32:56: Accounting response Jan 29 12:32:56: ...Done Accounting/Stop/answer/VoIP in 0.007022 seconds, 0.002577 spent in SQL queries. --REQUEST REQUEST-- Jan 29 12:32:56: 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 = 'Stop' h323-call-origin = 'answer' h323-call-type = 'VoIP' h323-setup-time = '20:29:03 GMT Fri Jan 29 2010' h323-connect-time = '20:29:12 GMT Fri Jan 29 2010' h323-disconnect-time = '20:30:56 GMT Fri Jan 29 2010' h323-disconnect-cause = '10' h323-conf-id = '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A' call-id = '94.23.242.200-1264796943.138' Acct-Session-Time = '104' session-protocol = 'sipv2' h323-remote-address = '94.23.242.200' Exec-Program-Log = 'porta-billing.pl' Jan 29 12:32:56: h323-conf-id=6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1, call-id=94.23.242.200-1264796943.138/1 Jan 29 12:32:56: Found a call in cache with such id Jan 29 12:32:56: PrepareNexecute 'GetActiveLegIdByAcct' Jan 29 12:32:56: SQL query 'GetActiveLegIdByAcct' executed in 0.002258 seconds Jan 29 12:32:56: End of call on incoming call leg from access NAS Jan 29 12:32:56: No logged in accounts, call lifetime reduced to 15 Jan 29 12:32:56: Set lifetime with 15s to Fri Jan 29 12:33:11 2010 Jan 29 12:32:56: Looking up vendor/connection Jan 29 12:32:56: Trying to match connection for call Jan 29 12:32:56: Looking for a connection VoIP/answer Jan 29 12:32:56: VoIP, matching by the node IP '94.23.242.200' and User-Name '41215500329' Jan 29 12:32:56: No VoIP from vendor connections were found Jan 29 12:32:56: Connection to vendor not found Jan 29 12:32:56: No connection from vendor Jan 29 12:32:56: Accounting response Jan 29 12:32:56: ...Done Accounting/Stop/answer/VoIP in 0.007478 seconds, 0.002258 spent in SQL queries. --REQUEST CALL-- Jan 29 12:33:22: Removing call 6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1 Jan 29 12:33:22: No logged in accounts, call lifetime reduced to 15 Jan 29 12:33:22: Cleaning up the call Jan 29 12:33:22: No originate call legs to replace username on, probably junk incoming call Jan 29 12:33:22: Processing answer/VoIP call leg Jan 29 12:33:22: Processing answer/VoIP call leg Jan 29 12:33:22: Found not billed accounting request with the duration more than zero - bill it now Jan 29 12:33:22: Looking up vendor/connection Jan 29 12:33:22: Trying to match connection for call Jan 29 12:33:22: Looking for a connection VoIP/answer Jan 29 12:33:22: VoIP, matching by the node IP '94.23.225.212' and User-Name '94.23.242.200' Jan 29 12:33:22: No VoIP from vendor connections were found Jan 29 12:33:22: Connection to vendor not found Jan 29 12:33:22: Charging call ... Jan 29 12:33:22: This is incoming call, bill only vendor Jan 29 12:33:22: Vendor is undefined (on-net call?), call is not billed Jan 29 12:33:22: No outgoing connections to vendor, on-net call Jan 29 12:33:22: No originate call legs, junk incoming call Jan 29 12:33:22: Call '6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1' deleted from the cache Jan 29 12:33:22: Call 6CDDD7AA 52ABE6AF 61AF83D1 6DF98D1A/1 removed --CALL