[Jan 9 14:26:14] Asterisk Ready. ]1;Asterisk]2;Asterisk Console on 'asteriskback' (pid 8850)*CLI> set debug 4 Core debug was 5 and is now 4 The 'set debug' command is deprecated and will be removed in a future release. Please use 'core set debug' instead. *CLI> set verbose 4 Verbosity was 5 and is now 4 The 'set verbose' command is deprecated and will be removed in a future release. Please use 'core set verbose' instead. *CLI> sip debug SIP Debugging enabled The 'sip debug' command is deprecated and will be removed in a future release. Please use 'sip set debug' instead. *CLI> [Jan 9 14:27:04] -- Attempting call on Local/333@clixme_initiate_call/n for 4012703950@clixme_initiate_call:1 (Retry 1) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:1] Set("Local/333@clixme_initiate_call-316e,2", "_LANG=us") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:2] Set("Local/333@clixme_initiate_call-316e,2", "_VENDOR_ID=1") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '09012007-14:27:04' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'NoOp' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:3] NoOp("Local/333@clixme_initiate_call-316e,2", "======TESTING HERE ======: 09012007-14:27:04") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'NoOp' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:4] NoOp("Local/333@clixme_initiate_call-316e,2", "======EPOCH ======: 1168370824") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:5] Set("Local/333@clixme_initiate_call-316e,2", "CLX_SNT=CID:15!CNO:4012703950!DID:1!EXT:!INITIP:192.168.0.3!LANG:us!VID:1!") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:6] Set("Local/333@clixme_initiate_call-316e,2", "max_pairs=7") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:7] Set("Local/333@clixme_initiate_call-316e,2", "loop=1") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'CID:15' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:8] Set("Local/333@clixme_initiate_call-316e,2", "Pair=CID:15") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:9] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?EndSearch:CheckLoop") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,10) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:10] GotoIf("Local/333@clixme_initiate_call-316e,2", "1?ContSearch:FromBegining") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,11) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '2' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:11] Set("Local/333@clixme_initiate_call-316e,2", "loop=2") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'CID' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:12] Set("Local/333@clixme_initiate_call-316e,2", "PairKey=CID") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:13] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveLang:TryNextVar1") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,16) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:16] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveVend:SearchItem") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,8) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'CNO:4012703950' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:8] Set("Local/333@clixme_initiate_call-316e,2", "Pair=CNO:4012703950") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:9] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?EndSearch:CheckLoop") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,10) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:10] GotoIf("Local/333@clixme_initiate_call-316e,2", "1?ContSearch:FromBegining") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,11) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '3' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:11] Set("Local/333@clixme_initiate_call-316e,2", "loop=3") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'CNO' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:12] Set("Local/333@clixme_initiate_call-316e,2", "PairKey=CNO") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:13] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveLang:TryNextVar1") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,16) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:16] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveVend:SearchItem") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,8) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DID:1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:8] Set("Local/333@clixme_initiate_call-316e,2", "Pair=DID:1") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:9] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?EndSearch:CheckLoop") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,10) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:10] GotoIf("Local/333@clixme_initiate_call-316e,2", "1?ContSearch:FromBegining") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,11) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '4' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:11] Set("Local/333@clixme_initiate_call-316e,2", "loop=4") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DID' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:12] Set("Local/333@clixme_initiate_call-316e,2", "PairKey=DID") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:13] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveLang:TryNextVar1") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,16) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:16] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveVend:SearchItem") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,8) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'EXT:' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:8] Set("Local/333@clixme_initiate_call-316e,2", "Pair=EXT:") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:9] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?EndSearch:CheckLoop") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,10) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:10] GotoIf("Local/333@clixme_initiate_call-316e,2", "1?ContSearch:FromBegining") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,11) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '5' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:11] Set("Local/333@clixme_initiate_call-316e,2", "loop=5") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'EXT' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:12] Set("Local/333@clixme_initiate_call-316e,2", "PairKey=EXT") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:13] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveLang:TryNextVar1") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,16) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:16] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveVend:SearchItem") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,8) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'INITIP:192.168.0.3' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:8] Set("Local/333@clixme_initiate_call-316e,2", "Pair=INITIP:192.168.0.3") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:9] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?EndSearch:CheckLoop") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,10) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:10] GotoIf("Local/333@clixme_initiate_call-316e,2", "1?ContSearch:FromBegining") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,11) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '6' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:11] Set("Local/333@clixme_initiate_call-316e,2", "loop=6") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'INITIP' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:12] Set("Local/333@clixme_initiate_call-316e,2", "PairKey=INITIP") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:13] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveLang:TryNextVar1") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,16) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:16] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveVend:SearchItem") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,8) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'LANG:us' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:8] Set("Local/333@clixme_initiate_call-316e,2", "Pair=LANG:us") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:9] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?EndSearch:CheckLoop") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,10) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:10] GotoIf("Local/333@clixme_initiate_call-316e,2", "1?ContSearch:FromBegining") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,11) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '7' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:11] Set("Local/333@clixme_initiate_call-316e,2", "loop=7") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'LANG' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:12] Set("Local/333@clixme_initiate_call-316e,2", "PairKey=LANG") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:13] GotoIf("Local/333@clixme_initiate_call-316e,2", "1?HaveLang:TryNextVar1") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,14) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'us' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:14] Set("Local/333@clixme_initiate_call-316e,2", "CustLang=us") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:15] Set("Local/333@clixme_initiate_call-316e,2", "_LANG=us") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:16] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveVend:SearchItem") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,8) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'VID:1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:8] Set("Local/333@clixme_initiate_call-316e,2", "Pair=VID:1") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:9] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?EndSearch:CheckLoop") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,10) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:10] GotoIf("Local/333@clixme_initiate_call-316e,2", "1?ContSearch:FromBegining") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,11) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '8' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:11] Set("Local/333@clixme_initiate_call-316e,2", "loop=8") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'VID' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:12] Set("Local/333@clixme_initiate_call-316e,2", "PairKey=VID") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:13] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?HaveLang:TryNextVar1") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,16) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:16] GotoIf("Local/333@clixme_initiate_call-316e,2", "1?HaveVend:SearchItem") in new stack [Jan 9 14:27:04] -- Goto (clixme_initiate_call,333,17) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:17] Set("Local/333@clixme_initiate_call-316e,2", "_VENDOR_ID=1") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '4012703950' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:18] Set("Local/333@clixme_initiate_call-316e,2", "_CALLED_NUMBER=4012703950") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:19] Set("Local/333@clixme_initiate_call-316e,2", "_SOUND_PATH=clixme") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:20] Set("Local/333@clixme_initiate_call-316e,2", "_CLIXME_BUSY_RETRY_DELAY=300") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:21] Set("Local/333@clixme_initiate_call-316e,2", "_CLIXME_PREFIX=1") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:22] Set("Local/333@clixme_initiate_call-316e,2", "_CLIXME_GATEWAY=verizon") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '4012703950' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:23] Set("Local/333@clixme_initiate_call-316e,2", "_ANNOUNCE_NUMBER=14012703950") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:24] Set("Local/333@clixme_initiate_call-316e,2", "_VEND_RESP=3") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:25] Set("Local/333@clixme_initiate_call-316e,2", "_LEG2_UNAVAILABLE=0") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:26] Set("Local/333@clixme_initiate_call-316e,2", "_CUST_BUSY=0") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:27] Set("Local/333@clixme_initiate_call-316e,2", "_CLX_HARD_DISCONNECT=10") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:28] Set("Local/333@clixme_initiate_call-316e,2", "_VENDOR_NO=0") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:29] Set("Local/333@clixme_initiate_call-316e,2", "_DEPT_CALLER_ID=0") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '4012703950' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'SIPAddHeader' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:30] SIPAddHeader("Local/333@clixme_initiate_call-316e,2", "P-Asserted-Identity: ") in new stack [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:16813 sip_addheader: SIP Header added "P-Asserted-Identity: " as _SIPADDHEADER01 [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Goto' [Jan 9 14:27:04] -- Executing [333@clixme_initiate_call:31] Goto("Local/333@clixme_initiate_call-316e,2", "clixme_agi|1|DialAgain") in new stack [Jan 9 14:27:04] -- Goto (clixme_agi,1,2) [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [1@clixme_agi:2] Set("Local/333@clixme_initiate_call-316e,2", "LIMIT_WARNING_FILE=clixme/us/balance-one-minute") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '316e,2' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [1@clixme_agi:3] Set("Local/333@clixme_initiate_call-316e,2", "chn_part2=316e,2") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '316e' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [1@clixme_agi:4] Set("Local/333@clixme_initiate_call-316e,2", "chn_id=316e") in new stack [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'SetGlobalVar' [Jan 9 14:27:04] -- Executing [1@clixme_agi:5] SetGlobalVar("Local/333@clixme_initiate_call-316e,2", "LIMIT_WARNING_FILE_316e=clixme/us/balance-one-minute") in new stack [Jan 9 14:27:04] WARNING[8882]: pbx.c:5880 pbx_builtin_setglobalvar: SetGlobalVar is deprecated. Please use Set(GLOBAL(LIMIT_WARNING_FILE_316e)=clixme/us/balance-one-minute) instead. [Jan 9 14:27:04] == Setting global variable 'LIMIT_WARNING_FILE_316e' to 'clixme/us/balance-one-minute' [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:04] -- Executing [1@clixme_agi:6] Set("Local/333@clixme_initiate_call-316e,2", "TIMEOUT(response)=360") in new stack [Jan 9 14:27:04] -- Response timeout set to 360 [Jan 9 14:27:04] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'AGI' [Jan 9 14:27:04] -- Executing [1@clixme_agi:7] AGI("Local/333@clixme_initiate_call-316e,2", "PrepaidCallClixme") in new stack [Jan 9 14:27:04] -- Launched AGI Script /var/lib/asterisk/agi-bin/PrepaidCallClixme [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (HAS_PREPAID_BALANCE=1) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (spt_channel=Local/333@clixme_initiate_call-316e,2) [Jan 9 14:27:04] -- AGI Script Executing Application: (SetGlobalVar) Options: (CLIXME_GATEWAY_316e=verizon) [Jan 9 14:27:04] == Setting global variable 'CLIXME_GATEWAY_316e' to 'verizon' [Jan 9 14:27:04] -- AGI Script Executing Application: (SetGlobalVar) Options: (CLIXME_PREFIX_316e=1) [Jan 9 14:27:04] == Setting global variable 'CLIXME_PREFIX_316e' to '1' [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (CALLED_NUMBER=) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (CALLING_CARD=4012703950) [Jan 9 14:27:04] -- AGI Script Executing Application: (SetGlobalVar) Options: (CLX_EXT_316e=) [Jan 9 14:27:04] == Setting global variable 'CLX_EXT_316e' to '' [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (CLX_EXT=) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (CLX_INITIP=192.168.0.3) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (spt_time=2007-01-09_14:27:04) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (vendor_id=1) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (group_id=1) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (customer_id=15) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (dept_id=1) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (affiliate_id=0) [Jan 9 14:27:04] -- AGI Script Executing Application: (SetGlobalVar) Options: (ENABLE_AUTORECHARGE_316e=0) [Jan 9 14:27:04] == Setting global variable 'ENABLE_AUTORECHARGE_316e' to '0' [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (PREPAID_BALANCE=516.913) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (AUTORECHARGE_LOW_THRESHOLD=25) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (CLX_COMPANY_NAME=Degreko) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (str_currency=USD) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (str_dialstring=4012703950) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (rate_per_minute=0.15) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (first_minute_rate=0.25) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (is_on_net=0) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (id=327) [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (country_name=Local-Call) [Jan 9 14:27:04] -- AGI Script Executing Application: (SetGlobalVar) Options: (CLX_HARD_DISCONNECT_316e=3445) [Jan 9 14:27:04] == Setting global variable 'CLX_HARD_DISCONNECT_316e' to '3445' [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (CLX_DEPT_NAME=degreko.com) [Jan 9 14:27:04] -- AGI Script Executing Application: (SetGlobalVar) Options: (DEPT_CALLER_ID_316e=8667674187) [Jan 9 14:27:04] == Setting global variable 'DEPT_CALLER_ID_316e' to '8667674187' [Jan 9 14:27:04] -- AGI Script Executing Application: (SetGlobalVar) Options: (HIST_PP_ID_316e=5450) [Jan 9 14:27:04] == Setting global variable 'HIST_PP_ID_316e' to '5450' [Jan 9 14:27:04] -- AGI Script Executing Application: (Set) Options: (PREPAID_DIALSTRING=SIP/14016411072@verizon) [Jan 9 14:27:04] -- AGI Script Executing Application: (SetGlobalVar) Options: (VENDOR_NO_316e=4016411072) [Jan 9 14:27:04] == Setting global variable 'VENDOR_NO_316e' to '4016411072' [Jan 9 14:27:04] -- AGI Script Executing Application: (DIAL) Options: (SIP/14016411072@verizon|90|M(clixme-vendor^1^15^1^316e^)) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:15106 sip_request_call: Asked to create a SIP channel with formats: 0x40 (slin) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4264 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:3766 sip_new: *** Our native formats are 0x8 (alaw) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:3767 sip_new: *** Joint capabilities are 0x0 (nothing) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:3768 sip_new: *** Our capabilities are 0xc (ulaw|alaw) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:3769 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:3771 sip_new: *** Our preferred formats from the incoming channel are 0x40 (slin) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:3792 sip_new: This channel will not be able to handle video. [Jan 9 14:27:04] DEBUG[8882]: rtp.c:1536 ast_rtp_make_compatible: Channel 'Local/333@clixme_initiate_call-316e,2' has no RTP, not doing anything [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable PREPAID_DIALSTRING. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CLX_DEPT_NAME. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable country_name. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable id. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable is_on_net. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable first_minute_rate. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable rate_per_minute. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable str_dialstring. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable str_currency. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CLX_COMPANY_NAME. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable AUTORECHARGE_LOW_THRESHOLD. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable PREPAID_BALANCE. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable affiliate_id. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable dept_id. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable customer_id. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable group_id. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable vendor_id. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable spt_time. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CLX_INITIP. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CLX_EXT. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CALLING_CARD. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CALLED_NUMBER. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable spt_channel. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable HAS_PREPAID_BALANCE. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_agi-1-7. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_agi-1-6. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_agi-1-5. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable chn_id. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_agi-1-4. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable chn_part2. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_agi-1-3. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable LIMIT_WARNING_FILE. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_agi-1-2. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-31. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER01. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-30. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable DEPT_CALLER_ID. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-29. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable VENDOR_NO. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-28. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable CLX_HARD_DISCONNECT. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-27. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable CUST_BUSY. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-26. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable LEG2_UNAVAILABLE. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-25. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable VEND_RESP. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-24. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable ANNOUNCE_NUMBER. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-23. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable CLIXME_GATEWAY. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-22. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable CLIXME_PREFIX. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-21. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable CLIXME_BUSY_RETRY_DELAY. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-20. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable SOUND_PATH. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-19. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-18. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-17. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-16. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-13. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable PairKey. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-12. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable loop. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-11. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-10. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-9. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable Pair. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-8. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable LANG. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-15. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CustLang. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-14. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-7. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable max_pairs. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-6. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CLX_SNT. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-5. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-4. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-3. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-2. [Jan 9 14:27:04] DEBUG[8882]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-333-1. [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:2812 sip_call: Outgoing Call for 14016411072 [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:2826 sip_call: Our T38 capability (0), joint T38 capability (0) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:6759 transmit_invite: Adding SIP Header "P-Asserted-Identity" with content :: [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:6122 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: False [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:6123 add_sdp: ** Our prefcodec: 0x40 (slin) [Jan 9 14:27:04] Audio is at 63.118.244.80 port 18154 [Jan 9 14:27:04] Adding codec 0x8 (alaw) to SDP [Jan 9 14:27:04] Adding codec 0x4 (ulaw) to SDP [Jan 9 14:27:04] Adding non-codec 0x1 (telephone-event) to SDP [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:6254 add_sdp: -- Done with adding codecs to SDP [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:6299 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 0: INVITE sip:14016411072@63.79.178.192 SIP/2.0 (44) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK167d95d1;rport (64) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 2: From: "4012703950" ;tag=as5077fa0c (64) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 3: To: (35) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 4: Contact: (39) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 5: Call-ID: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 (55) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 6: CSeq: 102 INVITE (16) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 8: Max-Forwards: 70 (16) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 9: Date: Tue, 09 Jan 2007 19:27:04 GMT (35) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 11: Supported: replaces (19) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 12: P-Asserted-Identity: (53) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 13: Content-Type: application/sdp (29) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 14: Content-Length: 264 (19) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4527 parse_request: Header 15: (0) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: v=0 (3) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: o=root 8850 8850 IN IP4 63.118.244.80 (37) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: s=session (9) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: c=IN IP4 63.118.244.80 (22) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: t=0 0 (5) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: m=audio 18154 RTP/AVP 8 0 101 (29) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: a=fmtp:101 0-16 (15) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: a=silenceSupp:off - - - - (25) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: a=ptime:20 (10) [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:4559 parse_request: Line: a=sendrecv (10) [Jan 9 14:27:04] Reliably Transmitting (no NAT) to 63.79.178.192:5060: INVITE sip:14016411072@63.79.178.192 SIP/2.0 Via: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK167d95d1;rport From: "4012703950" ;tag=as5077fa0c To: Contact: Call-ID: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Tue, 09 Jan 2007 19:27:04 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces P-Asserted-Identity: Content-Type: application/sdp Content-Length: 264 v=0 o=root 8850 8850 IN IP4 63.118.244.80 s=session c=IN IP4 63.118.244.80 t=0 0 m=audio 18154 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jan 9 14:27:04] DEBUG[8882]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7 [Jan 9 14:27:04] -- Called 14016411072@verizon [Jan 9 14:27:04] DEBUG[8882]: channel.c:2731 set_format: Set channel SIP/verizon-08a34868 to read format slin [Jan 9 14:27:04] DEBUG[8882]: channel.c:2731 set_format: Set channel Local/333@clixme_initiate_call-316e,2 to read format alaw [Jan 9 14:27:04] <--- SIP read from 63.79.178.192:5060 ---> SIP/2.0 100 Trying v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK167d95d1;rport;received=63.118.244.80 f: "4012703950" ;tag=as5077fa0c t: i: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 CSeq: 102 INVITE l: 0 <-------------> [Jan 9 14:27:04] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 0: SIP/2.0 100 Trying (18) [Jan 9 14:27:04] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 1: v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK167d95d1;rport;received=63.118.244.80 (85) [Jan 9 14:27:04] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 2: f: "4012703950" ;tag=as5077fa0c (61) [Jan 9 14:27:04] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 3: t: (34) [Jan 9 14:27:04] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 4: i: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 (49) [Jan 9 14:27:04] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 5: CSeq: 102 INVITE (16) [Jan 9 14:27:04] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 6: l: 0 (4) [Jan 9 14:27:04] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 7: (0) [Jan 9 14:27:04] --- (7 headers 0 lines) --- [Jan 9 14:27:04] DEBUG[8858]: chan_sip.c:2104 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #7 - INVITE (got response) [Jan 9 14:27:04] DEBUG[8858]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0ea3e4236ddd388235379c0c7a646b58@63.118.244.80' Request 102: Found [Jan 9 14:27:04] DEBUG[8858]: chan_sip.c:11531 handle_response_invite: SIP response 100 to standard invite [Jan 9 14:27:05] <--- SIP read from 63.79.178.192:5060 ---> SIP/2.0 183 Session Progress v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK167d95d1;rport;received=63.118.244.80 f: "4012703950" ;tag=as5077fa0c t: ;tag=A20F0D18-19F4 Date: Tue, 09 Jan 2007 19:21:50 GMT i: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: UPDATE Allow-Events: telephone-event m: Record-Route: Content-Disposition: session;handling=required c: application/sdp l: 244 v=0 o=CiscoSystemsSIP-GW-UserAgent 5846 1929 IN IP4 63.79.178.4 s=SIP Call c=IN IP4 63.79.178.4 t=0 0 m=audio 16940 RTP/AVP 8 101 c=IN IP4 63.79.178.4 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 <-------------> [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 0: SIP/2.0 183 Session Progress (28) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 1: v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK167d95d1;rport;received=63.118.244.80 (85) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 2: f: "4012703950" ;tag=as5077fa0c (61) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 3: t: ;tag=A20F0D18-19F4 (52) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 4: Date: Tue, 09 Jan 2007 19:21:50 GMT (35) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 5: i: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 (49) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 7: CSeq: 102 INVITE (16) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 8: Allow: UPDATE (13) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 9: Allow-Events: telephone-event (29) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 10: m: (44) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 11: Record-Route: (36) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 12: Content-Disposition: session;handling=required (46) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 13: c: application/sdp (18) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 14: l: 244 (6) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 15: (0) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: v=0 (3) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 5846 1929 IN IP4 63.79.178.4 (59) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: s=SIP Call (10) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: c=IN IP4 63.79.178.4 (20) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: t=0 0 (5) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: m=audio 16940 RTP/AVP 8 101 (27) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: c=IN IP4 63.79.178.4 (20) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=fmtp:101 0-16 (15) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=ptime:20 (10) [Jan 9 14:27:05] --- (15 headers 11 lines) --- [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0ea3e4236ddd388235379c0c7a646b58@63.118.244.80' Request 102: Found [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:11531 handle_response_invite: SIP response 183 to standard invite [Jan 9 14:27:05] Found RTP audio format 8 [Jan 9 14:27:05] Found RTP audio format 101 [Jan 9 14:27:05] Peer audio RTP is at port 63.79.178.4:16940 [Jan 9 14:27:05] Found description format PCMA for ID 8 [Jan 9 14:27:05] Found description format telephone-event for ID 101 [Jan 9 14:27:05] Got unsupported a:fmtp in SDP offer [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:5068 process_sdp: T38 state changed to 0 on channel SIP/verizon-08a34868 [Jan 9 14:27:05] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Jan 9 14:27:05] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jan 9 14:27:05] Peer audio RTP is at port 63.79.178.4:16940 [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:5145 process_sdp: We're settling with these formats: 0x8 (alaw) [Jan 9 14:27:05] DEBUG[8858]: chan_sip.c:5152 process_sdp: We have an owner, now see if we need to change this call [Jan 9 14:27:05] -- SIP/verizon-08a34868 is making progress passing it to Local/333@clixme_initiate_call-316e,2 [Jan 9 14:27:05] DEBUG[8882]: rtp.c:1457 ast_rtp_early_bridge: Channel 'Local/333@clixme_initiate_call-316e,2' has no RTP, not doing anything [Jan 9 14:27:07] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 108 bytes [Jan 9 14:27:09] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 108 bytes [Jan 9 14:27:13] DEBUG[8863]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/616 [Jan 9 14:27:13] DEBUG[8854]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 616 [Jan 9 14:27:13] DEBUG[8854]: chan_iax2.c:9600 iax2_devicestate: Checking device state for device 616 [Jan 9 14:27:13] DEBUG[8854]: chan_iax2.c:9608 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 616? addr=50374848, defaddr=0 maxms=0, lastms=0 [Jan 9 14:27:13] DEBUG[8854]: devicestate.c:287 do_state_change: Changing state for IAX2/616 - state 1 (Not in use) [Jan 9 14:27:13] DEBUG[8884]: app_queue.c:546 changethread: Device 'IAX2/616' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 9 14:27:13] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 108 bytes [Jan 9 14:27:16] <--- SIP read from 63.79.178.192:5060 ---> SIP/2.0 200 OK v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK167d95d1;rport;received=63.118.244.80 f: "4012703950" ;tag=as5077fa0c t: ;tag=A20F0D18-19F4 Date: Tue, 09 Jan 2007 19:21:50 GMT i: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER Allow-Events: telephone-event m: Record-Route: c: application/sdp l: 244 Warning: 399 63.79.178.192 "Call Placed by Non-Trusted User" v=0 o=CiscoSystemsSIP-GW-UserAgent 5846 1929 IN IP4 63.79.178.4 s=SIP Call c=IN IP4 63.79.178.4 t=0 0 m=audio 16940 RTP/AVP 8 101 c=IN IP4 63.79.178.4 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 <-------------> [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 1: v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK167d95d1;rport;received=63.118.244.80 (85) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 2: f: "4012703950" ;tag=as5077fa0c (61) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 3: t: ;tag=A20F0D18-19F4 (52) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 4: Date: Tue, 09 Jan 2007 19:21:50 GMT (35) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 5: i: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 (49) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 7: CSeq: 102 INVITE (16) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 8: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER (104) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 9: Allow-Events: telephone-event (29) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 10: m: (44) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 11: Record-Route: (36) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 12: c: application/sdp (18) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 13: l: 244 (6) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 14: Warning: 399 63.79.178.192 "Call Placed by Non-Trusted User" (60) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 15: (0) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: v=0 (3) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 5846 1929 IN IP4 63.79.178.4 (59) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: s=SIP Call (10) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: c=IN IP4 63.79.178.4 (20) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: t=0 0 (5) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: m=audio 16940 RTP/AVP 8 101 (27) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: c=IN IP4 63.79.178.4 (20) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=fmtp:101 0-16 (15) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=ptime:20 (10) [Jan 9 14:27:16] --- (15 headers 11 lines) --- [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:2053 __sip_ack: Acked pending invite 102 [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '0ea3e4236ddd388235379c0c7a646b58@63.118.244.80' of Request 102: Match Not Found [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:11531 handle_response_invite: SIP response 200 to standard invite [Jan 9 14:27:16] Found RTP audio format 8 [Jan 9 14:27:16] Found RTP audio format 101 [Jan 9 14:27:16] Peer audio RTP is at port 63.79.178.4:16940 [Jan 9 14:27:16] Found description format PCMA for ID 8 [Jan 9 14:27:16] Found description format telephone-event for ID 101 [Jan 9 14:27:16] Got unsupported a:fmtp in SDP offer [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:5068 process_sdp: T38 state changed to 0 on channel SIP/verizon-08a34868 [Jan 9 14:27:16] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Jan 9 14:27:16] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jan 9 14:27:16] Peer audio RTP is at port 63.79.178.4:16940 [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:5145 process_sdp: We're settling with these formats: 0x8 (alaw) [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:5152 process_sdp: We have an owner, now see if we need to change this call [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Jan 9 14:27:16] DEBUG[8858]: chan_sip.c:7862 build_route: build_route: Record-Route hop: [Jan 9 14:27:16] list_route: hop: [Jan 9 14:27:16] set_destination: Parsing for address/port to send to [Jan 9 14:27:16] set_destination: set destination to 63.79.178.192, port 5060 [Jan 9 14:27:16] Transmitting (no NAT) to 63.79.178.192:5060: ACK sip:333010814016411072@63.79.178.4:5060 SIP/2.0 Via: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK10740490;rport Route: From: "4012703950" ;tag=as5077fa0c To: ;tag=A20F0D18-19F4 Contact: Call-ID: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Jan 9 14:27:16] DEBUG[8882]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/verizon-08a34868 [Jan 9 14:27:16] -- SIP/verizon-08a34868 answered Local/333@clixme_initiate_call-316e,2 [Jan 9 14:27:16] DEBUG[8854]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - verizon [Jan 9 14:27:16] DEBUG[8882]: rtp.c:1457 ast_rtp_early_bridge: Channel 'Local/333@clixme_initiate_call-316e,2' has no RTP, not doing anything [Jan 9 14:27:16] DEBUG[8854]: chan_sip.c:15048 sip_devicestate: Checking device state for peer verizon [Jan 9 14:27:16] DEBUG[8854]: devicestate.c:287 do_state_change: Changing state for SIP/verizon - state 1 (Not in use) [Jan 9 14:27:16] DEBUG[8886]: app_queue.c:546 changethread: Device 'SIP/verizon' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 9 14:27:16] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'AGI' [Jan 9 14:27:16] -- Executing [s@macro-clixme-vendor:1] AGI("SIP/verizon-08a34868", "CheckFileExist|CLX_CUST_YOUHAVE|/var/lib/asterisk/sounds/clixme/us/clx_custom/youhave_1-15-1.wav") in new stack [Jan 9 14:27:16] -- Launched AGI Script /var/lib/asterisk/agi-bin/CheckFileExist [Jan 9 14:27:16] -- AGI Script Executing Application: (SetGlobalVar) Options: (CLX_CUST_YOUHAVE=1) [Jan 9 14:27:16] == Setting global variable 'CLX_CUST_YOUHAVE' to '1' [Jan 9 14:27:16] -- AGI Script CheckFileExist completed, returning 0 [Jan 9 14:27:16] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'AGI' [Jan 9 14:27:16] -- Executing [s@macro-clixme-vendor:2] AGI("SIP/verizon-08a34868", "CheckFileExist|CLX_CUST_EXT|/var/lib/asterisk/sounds/clixme/us/clx_custom/clixme-ext_1-15-1.wav") in new stack [Jan 9 14:27:16] -- Launched AGI Script /var/lib/asterisk/agi-bin/CheckFileExist [Jan 9 14:27:16] -- AGI Script Executing Application: (SetGlobalVar) Options: (CLX_CUST_EXT=1) [Jan 9 14:27:16] == Setting global variable 'CLX_CUST_EXT' to '1' [Jan 9 14:27:16] -- AGI Script CheckFileExist completed, returning 0 [Jan 9 14:27:16] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:16] -- Executing [s@macro-clixme-vendor:3] Set("SIP/verizon-08a34868", "ACCEPT=") in new stack [Jan 9 14:27:16] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:16] -- Executing [s@macro-clixme-vendor:4] Set("SIP/verizon-08a34868", "ACCEPT_EARLIER=") in new stack [Jan 9 14:27:16] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'SetGlobalVar' [Jan 9 14:27:16] -- Executing [s@macro-clixme-vendor:5] SetGlobalVar("SIP/verizon-08a34868", "G_VEND_RESP_316e=3") in new stack [Jan 9 14:27:16] == Setting global variable 'G_VEND_RESP_316e' to '3' [Jan 9 14:27:16] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:16] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:16] -- Executing [s@macro-clixme-vendor:6] GotoIf("SIP/verizon-08a34868", "0?WithExt:Normal") in new stack [Jan 9 14:27:16] -- Goto (macro-clixme-vendor,s,22) [Jan 9 14:27:16] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:16] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:16] -- Executing [s@macro-clixme-vendor:22] GotoIf("SIP/verizon-08a34868", "1?PlayCust:PlayNormal") in new stack [Jan 9 14:27:16] -- Goto (macro-clixme-vendor,s,23) [Jan 9 14:27:16] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Playback' [Jan 9 14:27:16] -- Executing [s@macro-clixme-vendor:23] Playback("SIP/verizon-08a34868", "clixme/us/clx_custom/youhave_1-15-1") in new stack [Jan 9 14:27:16] DEBUG[8882]: channel.c:2731 set_format: Set channel SIP/verizon-08a34868 to write format slin [Jan 9 14:27:16] DEBUG[8882]: rtp.c:2647 ast_rtp_write: Ooh, format changed from unknown to alaw [Jan 9 14:27:16] DEBUG[8882]: rtp.c:2664 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Jan 9 14:27:16] -- Playing 'clixme/us/clx_custom/youhave_1-15-1' (language 'en') [Jan 9 14:27:20] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:21] DEBUG[8882]: channel.c:2731 set_format: Set channel SIP/verizon-08a34868 to write format alaw [Jan 9 14:27:21] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Goto' [Jan 9 14:27:21] -- Executing [s@macro-clixme-vendor:24] Goto("SIP/verizon-08a34868", "NormRead") in new stack [Jan 9 14:27:21] -- Goto (macro-clixme-vendor,s,26) [Jan 9 14:27:21] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Playback' [Jan 9 14:27:21] -- Executing [s@macro-clixme-vendor:26] Playback("SIP/verizon-08a34868", "clixme/us/clixme-ext2") in new stack [Jan 9 14:27:21] DEBUG[8882]: channel.c:2731 set_format: Set channel SIP/verizon-08a34868 to write format gsm [Jan 9 14:27:21] -- Playing 'clixme/us/clixme-ext2' (language 'en') [Jan 9 14:27:26] DEBUG[8882]: channel.c:2731 set_format: Set channel SIP/verizon-08a34868 to write format alaw [Jan 9 14:27:26] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Playback' [Jan 9 14:27:26] -- Executing [s@macro-clixme-vendor:27] Playback("SIP/verizon-08a34868", "beep") in new stack [Jan 9 14:27:26] DEBUG[8882]: channel.c:2731 set_format: Set channel SIP/verizon-08a34868 to write format gsm [Jan 9 14:27:26] -- Playing 'beep' (language 'en') [Jan 9 14:27:26] DEBUG[8882]: channel.c:2731 set_format: Set channel SIP/verizon-08a34868 to write format alaw [Jan 9 14:27:26] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:26] -- Executing [s@macro-clixme-vendor:28] Set("SIP/verizon-08a34868", "TIMEOUT(response)=15") in new stack [Jan 9 14:27:26] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Read' [Jan 9 14:27:26] -- Executing [s@macro-clixme-vendor:29] Read("SIP/verizon-08a34868", "ACCEPT||1") in new stack [Jan 9 14:27:26] -- Accepting a maximum of 1 digits. [Jan 9 14:27:27] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:28] NOTICE[8882]: rtp.c:772 process_rfc3389: Comfort noise support incomplete in Asterisk (RFC 3389). Please turn off on client if possible. Client IP: 63.79.178.4 [Jan 9 14:27:28] DEBUG[8882]: rtp.c:718 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 9 14:27:28] DEBUG[8882]: rtp.c:617 send_dtmf: Sending dtmf: 49 (1), at 63.79.178.4 [Jan 9 14:27:28] DEBUG[8882]: rtp.c:718 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 9 14:27:28] DEBUG[8882]: rtp.c:718 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 9 14:27:28] DEBUG[8882]: rtp.c:718 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 9 14:27:28] DEBUG[8882]: rtp.c:718 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 9 14:27:28] DEBUG[8882]: rtp.c:718 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 9 14:27:28] DEBUG[8882]: rtp.c:718 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 9 14:27:28] DEBUG[8882]: rtp.c:617 send_dtmf: Sending dtmf: 49 (1), at 63.79.178.4 [Jan 9 14:27:28] -- User entered '1' [Jan 9 14:27:28] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'NoOp' [Jan 9 14:27:28] -- Executing [s@macro-clixme-vendor:30] NoOp("SIP/verizon-08a34868", "ACCEPT: 1") in new stack [Jan 9 14:27:28] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Goto' [Jan 9 14:27:28] -- Executing [s@macro-clixme-vendor:31] Goto("SIP/verizon-08a34868", "JumpRead") in new stack [Jan 9 14:27:28] -- Goto (macro-clixme-vendor,s,32) [Jan 9 14:27:28] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:28] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:28] -- Executing [s@macro-clixme-vendor:32] GotoIf("SIP/verizon-08a34868", "0?Refuse:JumpRead1") in new stack [Jan 9 14:27:28] -- Goto (macro-clixme-vendor,s,33) [Jan 9 14:27:28] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:28] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:28] -- Executing [s@macro-clixme-vendor:33] GotoIf("SIP/verizon-08a34868", "1?Accept:Refuse") in new stack [Jan 9 14:27:28] -- Goto (macro-clixme-vendor,s,37) [Jan 9 14:27:28] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'SetGlobalVar' [Jan 9 14:27:28] -- Executing [s@macro-clixme-vendor:37] SetGlobalVar("SIP/verizon-08a34868", "G_VEND_RESP_316e=1") in new stack [Jan 9 14:27:28] == Setting global variable 'G_VEND_RESP_316e' to '1' [Jan 9 14:27:28] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Playback' [Jan 9 14:27:28] -- Executing [s@macro-clixme-vendor:38] Playback("SIP/verizon-08a34868", "clixme/us/pls-wait-while-connect") in new stack [Jan 9 14:27:28] DEBUG[8882]: channel.c:2731 set_format: Set channel SIP/verizon-08a34868 to write format gsm [Jan 9 14:27:28] DEBUG[8882]: rtp.c:2517 ast_rtp_raw_write: Difference is 14536, ms is 1837 [Jan 9 14:27:28] -- Playing 'clixme/us/pls-wait-while-connect' (language 'en') [Jan 9 14:27:28] DEBUG[8882]: rtp.c:718 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 9 14:27:28] DEBUG[8882]: rtp.c:718 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 9 14:27:30] DEBUG[8882]: channel.c:2731 set_format: Set channel SIP/verizon-08a34868 to write format alaw [Jan 9 14:27:30] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'NoOp' [Jan 9 14:27:30] -- Executing [s@macro-clixme-vendor:39] NoOp("SIP/verizon-08a34868", "End Of Macro") in new stack [Jan 9 14:27:30] DEBUG[8882]: app_dial.c:1482 dial_exec_full: Macro exited with status 0 [Jan 9 14:27:30] DEBUG[8882]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/333@clixme_initiate_call-316e,2 [Jan 9 14:27:30] DEBUG[8881]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/333@clixme_initiate_call-316e,1 [Jan 9 14:27:30] > Channel Local/333@clixme_initiate_call-316e,1 was answered. [Jan 9 14:27:30] DEBUG[8854]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 333@clixme_initiate_call [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'NoOp' [Jan 9 14:27:30] DEBUG[8854]: chan_local.c:145 local_devicestate: Checking if extension 333@clixme_initiate_call exists (devicestate) [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:1] NoOp("Local/333@clixme_initiate_call-316e,1", "=========== SECOND LEG of call (clixme_initiate_call|_X.|1 extension) ================") in new stack [Jan 9 14:27:30] DEBUG[8854]: devicestate.c:287 do_state_change: Changing state for Local/333@clixme_initiate_call - state 2 (In use) [Jan 9 14:27:30] DEBUG[8854]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 333@clixme_initiate_call [Jan 9 14:27:30] DEBUG[8854]: chan_local.c:145 local_devicestate: Checking if extension 333@clixme_initiate_call exists (devicestate) [Jan 9 14:27:30] DEBUG[8854]: devicestate.c:287 do_state_change: Changing state for Local/333@clixme_initiate_call - state 2 (In use) [Jan 9 14:27:30] DEBUG[8889]: app_queue.c:546 changethread: Device 'Local/333@clixme_initiate_call' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '316e,1' [Jan 9 14:27:30] DEBUG[8890]: app_queue.c:546 changethread: Device 'Local/333@clixme_initiate_call' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:2] Set("Local/333@clixme_initiate_call-316e,1", "chn_part2=316e,1") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '316e' [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:3] Set("Local/333@clixme_initiate_call-316e,1", "chn_id=316e") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'SetGlobalVar' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:4] SetGlobalVar("Local/333@clixme_initiate_call-316e,1", "CUST_BUSY_316e=0") in new stack [Jan 9 14:27:30] == Setting global variable 'CUST_BUSY_316e' to '0' [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:5] Set("Local/333@clixme_initiate_call-316e,1", "ENABLE_AUTORECHARGE=0") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:6] Set("Local/333@clixme_initiate_call-316e,1", "LIMIT_WARNING_FILE=clixme/us/balance-one-minute") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:7] Set("Local/333@clixme_initiate_call-316e,1", "VEND_RESP=1") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:8] Set("Local/333@clixme_initiate_call-316e,1", "VENDOR_NO=4016411072") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:9] Set("Local/333@clixme_initiate_call-316e,1", "CLX_HARD_DISCONNECT=3445") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:10] GotoIf("Local/333@clixme_initiate_call-316e,1", "1?ResetHwdDisc:SetPrefix") in new stack [Jan 9 14:27:30] -- Goto (clixme_initiate_call,4012703950,11) [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '3444' [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:11] Set("Local/333@clixme_initiate_call-316e,1", "CLX_HARD_DISCONNECT=3444") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:12] Set("Local/333@clixme_initiate_call-316e,1", "CLIXME_GATEWAY=leg2verizon") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:13] Set("Local/333@clixme_initiate_call-316e,1", "CLX_EXT=") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:14] Set("Local/333@clixme_initiate_call-316e,1", "DEPT_CALLER_ID=8667674187") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:15] GotoIf("Local/333@clixme_initiate_call-316e,1", "1?ContSecondLeg:Hang") in new stack [Jan 9 14:27:30] -- Goto (clixme_initiate_call,4012703950,16) [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:16] GotoIf("Local/333@clixme_initiate_call-316e,1", "1?SetNewCID:NormalCID") in new stack [Jan 9 14:27:30] -- Goto (clixme_initiate_call,4012703950,17) [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:17] Set("Local/333@clixme_initiate_call-316e,1", "CALLERID(num)=8667674187") in new stack [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Goto' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:18] Goto("Local/333@clixme_initiate_call-316e,1", "CheckType") in new stack [Jan 9 14:27:30] -- Goto (clixme_initiate_call,4012703950,20) [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:20] GotoIf("Local/333@clixme_initiate_call-316e,1", "0?WithExt:Normal") in new stack [Jan 9 14:27:30] -- Goto (clixme_initiate_call,4012703950,25) [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'SIPAddHeader' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:25] SIPAddHeader("Local/333@clixme_initiate_call-316e,1", "P-Asserted-Identity: ") in new stack [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:16813 sip_addheader: SIP Header added "P-Asserted-Identity: " as _SIPADDHEADER01 [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '@leg2verizon' [Jan 9 14:27:30] DEBUG[8881]: pbx.c:1767 pbx_extension_helper: Launching 'Dial' [Jan 9 14:27:30] -- Executing [4012703950@clixme_initiate_call:26] Dial("Local/333@clixme_initiate_call-316e,1", "SIP/+14012703950@leg2verizon|90") in new stack [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:15106 sip_request_call: Asked to create a SIP channel with formats: 0x40 (slin) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4264 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:3766 sip_new: *** Our native formats are 0x8 (alaw) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:3767 sip_new: *** Joint capabilities are 0x0 (nothing) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:3768 sip_new: *** Our capabilities are 0x8 (alaw) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:3769 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:3771 sip_new: *** Our preferred formats from the incoming channel are 0x40 (slin) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:3792 sip_new: This channel will not be able to handle video. [Jan 9 14:27:30] DEBUG[8881]: rtp.c:1536 ast_rtp_make_compatible: Channel 'Local/333@clixme_initiate_call-316e,1' has no RTP, not doing anything [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-26. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER01. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-25. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-20. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-18. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-17. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-16. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-15. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable DEPT_CALLER_ID. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-14. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CLX_EXT. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-13. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CLIXME_GATEWAY. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-12. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CLX_HARD_DISCONNECT. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-11. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-10. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-9. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable VENDOR_NO. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-8. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable VEND_RESP. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-7. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable LIMIT_WARNING_FILE. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-6. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable ENABLE_AUTORECHARGE. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-5. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-4. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable chn_id. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-3. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable chn_part2. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-2. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-clixme_initiate_call-4012703950-1. [Jan 9 14:27:30] DEBUG[8881]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CLX_SNT. [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:2812 sip_call: Outgoing Call for +14012703950 [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:2826 sip_call: Our T38 capability (0), joint T38 capability (0) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:6759 transmit_invite: Adding SIP Header "P-Asserted-Identity" with content :: [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:6122 add_sdp: ** Our capability: 0x8 (alaw) Video flag: False [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:6123 add_sdp: ** Our prefcodec: 0x40 (slin) [Jan 9 14:27:30] Audio is at 63.118.244.80 port 13468 [Jan 9 14:27:30] Adding codec 0x8 (alaw) to SDP [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:6254 add_sdp: -- Done with adding codecs to SDP [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:6299 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 0: INVITE sip:+14012703950@63.79.178.194 SIP/2.0 (45) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK2354f210;rport (64) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 2: From: "8667674187" ;tag=as1ed0d396 (64) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 3: To: (36) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 4: Contact: (39) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 5: Call-ID: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 (55) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 6: CSeq: 102 INVITE (16) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 8: Max-Forwards: 70 (16) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 9: Date: Tue, 09 Jan 2007 19:27:30 GMT (35) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 11: Supported: replaces (19) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 12: P-Asserted-Identity: (52) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 13: Content-Type: application/sdp (29) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 14: Content-Length: 184 (19) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4527 parse_request: Header 15: (0) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4559 parse_request: Line: v=0 (3) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4559 parse_request: Line: o=root 8850 8850 IN IP4 63.118.244.80 (37) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4559 parse_request: Line: s=session (9) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4559 parse_request: Line: c=IN IP4 63.118.244.80 (22) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4559 parse_request: Line: t=0 0 (5) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4559 parse_request: Line: m=audio 13468 RTP/AVP 8 (23) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4559 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4559 parse_request: Line: a=silenceSupp:off - - - - (25) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4559 parse_request: Line: a=ptime:20 (10) [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:4559 parse_request: Line: a=sendrecv (10) [Jan 9 14:27:30] Reliably Transmitting (no NAT) to 63.79.178.194:5060: INVITE sip:+14012703950@63.79.178.194 SIP/2.0 Via: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK2354f210;rport From: "8667674187" ;tag=as1ed0d396 To: Contact: Call-ID: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Tue, 09 Jan 2007 19:27:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces P-Asserted-Identity: Content-Type: application/sdp Content-Length: 184 v=0 o=root 8850 8850 IN IP4 63.118.244.80 s=session c=IN IP4 63.118.244.80 t=0 0 m=audio 13468 RTP/AVP 8 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jan 9 14:27:30] DEBUG[8881]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #10 [Jan 9 14:27:30] -- Called +14012703950@leg2verizon [Jan 9 14:27:30] DEBUG[8881]: channel.c:2731 set_format: Set channel SIP/leg2verizon-08a42860 to read format slin [Jan 9 14:27:30] DEBUG[8881]: channel.c:2731 set_format: Set channel Local/333@clixme_initiate_call-316e,1 to read format alaw [Jan 9 14:27:30] <--- SIP read from 63.79.178.194:5060 ---> SIP/2.0 100 Trying v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK2354f210;rport;received=63.118.244.80 f: "8667674187" ;tag=as1ed0d396 t: i: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 CSeq: 102 INVITE l: 0 <-------------> [Jan 9 14:27:30] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 0: SIP/2.0 100 Trying (18) [Jan 9 14:27:30] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 1: v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK2354f210;rport;received=63.118.244.80 (85) [Jan 9 14:27:30] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 2: f: "8667674187" ;tag=as1ed0d396 (61) [Jan 9 14:27:30] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 3: t: (35) [Jan 9 14:27:30] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 4: i: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 (49) [Jan 9 14:27:30] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 5: CSeq: 102 INVITE (16) [Jan 9 14:27:30] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 6: l: 0 (4) [Jan 9 14:27:30] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 7: (0) [Jan 9 14:27:30] --- (7 headers 0 lines) --- [Jan 9 14:27:30] DEBUG[8858]: chan_sip.c:2104 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #10 - INVITE (got response) [Jan 9 14:27:30] DEBUG[8858]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80' Request 102: Found [Jan 9 14:27:30] DEBUG[8858]: chan_sip.c:11531 handle_response_invite: SIP response 100 to standard invite [Jan 9 14:27:33] <--- SIP read from 63.79.178.194:5060 ---> SIP/2.0 183 Session Progress v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK2354f210;rport;received=63.118.244.80 f: "8667674187" ;tag=as1ed0d396 t: ;tag=A20F71DC-1BBC Date: Tue, 09 Jan 2007 19:22:16 GMT i: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: UPDATE Allow-Events: telephone-event m: Record-Route: Content-Disposition: session;handling=required c: application/sdp l: 188 v=0 o=CiscoSystemsSIP-GW-UserAgent 2709 4288 IN IP4 63.79.178.4 s=SIP Call c=IN IP4 63.79.178.4 t=0 0 m=audio 17938 RTP/AVP 8 c=IN IP4 63.79.178.4 a=rtpmap:8 PCMA/8000 a=ptime:20 <-------------> [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 0: SIP/2.0 183 Session Progress (28) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 1: v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK2354f210;rport;received=63.118.244.80 (85) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 2: f: "8667674187" ;tag=as1ed0d396 (61) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 3: t: ;tag=A20F71DC-1BBC (53) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 4: Date: Tue, 09 Jan 2007 19:22:16 GMT (35) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 5: i: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 (49) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 7: CSeq: 102 INVITE (16) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 8: Allow: UPDATE (13) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 9: Allow-Events: telephone-event (29) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 10: m: (44) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 11: Record-Route: (36) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 12: Content-Disposition: session;handling=required (46) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 13: c: application/sdp (18) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 14: l: 188 (6) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 15: (0) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: v=0 (3) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 2709 4288 IN IP4 63.79.178.4 (59) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: s=SIP Call (10) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: c=IN IP4 63.79.178.4 (20) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: t=0 0 (5) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: m=audio 17938 RTP/AVP 8 (23) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: c=IN IP4 63.79.178.4 (20) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=ptime:20 (10) [Jan 9 14:27:33] --- (15 headers 9 lines) --- [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80' Request 102: Found [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:11531 handle_response_invite: SIP response 183 to standard invite [Jan 9 14:27:33] Found RTP audio format 8 [Jan 9 14:27:33] Peer audio RTP is at port 63.79.178.4:17938 [Jan 9 14:27:33] Found description format PCMA for ID 8 [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:5068 process_sdp: T38 state changed to 0 on channel SIP/leg2verizon-08a42860 [Jan 9 14:27:33] Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Jan 9 14:27:33] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jan 9 14:27:33] Peer audio RTP is at port 63.79.178.4:17938 [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:5145 process_sdp: We're settling with these formats: 0x8 (alaw) [Jan 9 14:27:33] DEBUG[8858]: chan_sip.c:5152 process_sdp: We have an owner, now see if we need to change this call [Jan 9 14:27:33] -- SIP/leg2verizon-08a42860 is making progress passing it to Local/333@clixme_initiate_call-316e,1 [Jan 9 14:27:33] DEBUG[8881]: rtp.c:1457 ast_rtp_early_bridge: Channel 'Local/333@clixme_initiate_call-316e,1' has no RTP, not doing anything [Jan 9 14:27:33] DEBUG[8882]: channel.c:3704 ast_generic_bridge: Got a FRAME_CONTROL (14) frame on channel Local/333@clixme_initiate_call-316e,2 [Jan 9 14:27:33] DEBUG[8882]: channel.c:3990 ast_channel_bridge: Bridge stops bridging channels Local/333@clixme_initiate_call-316e,2 and SIP/verizon-08a34868 [Jan 9 14:27:33] DEBUG[8881]: rtp.c:2647 ast_rtp_write: Ooh, format changed from unknown to alaw [Jan 9 14:27:33] DEBUG[8881]: rtp.c:2664 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Jan 9 14:27:33] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:35] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:38] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:38] <--- SIP read from 63.79.178.194:5060 ---> SIP/2.0 200 OK v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK2354f210;rport;received=63.118.244.80 f: "8667674187" ;tag=as1ed0d396 t: ;tag=A20F71DC-1BBC Date: Tue, 09 Jan 2007 19:22:16 GMT i: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER Allow-Events: telephone-event m: Record-Route: c: application/sdp l: 188 Warning: 399 63.79.178.194 "Call Placed by Non-Trusted User" v=0 o=CiscoSystemsSIP-GW-UserAgent 2709 4288 IN IP4 63.79.178.4 s=SIP Call c=IN IP4 63.79.178.4 t=0 0 m=audio 17938 RTP/AVP 8 c=IN IP4 63.79.178.4 a=rtpmap:8 PCMA/8000 a=ptime:20 <-------------> [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 1: v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK2354f210;rport;received=63.118.244.80 (85) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 2: f: "8667674187" ;tag=as1ed0d396 (61) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 3: t: ;tag=A20F71DC-1BBC (53) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 4: Date: Tue, 09 Jan 2007 19:22:16 GMT (35) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 5: i: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 (49) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 7: CSeq: 102 INVITE (16) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 8: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER (104) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 9: Allow-Events: telephone-event (29) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 10: m: (44) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 11: Record-Route: (36) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 12: c: application/sdp (18) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 13: l: 188 (6) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 14: Warning: 399 63.79.178.194 "Call Placed by Non-Trusted User" (60) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 15: (0) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: v=0 (3) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 2709 4288 IN IP4 63.79.178.4 (59) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: s=SIP Call (10) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: c=IN IP4 63.79.178.4 (20) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: t=0 0 (5) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: m=audio 17938 RTP/AVP 8 (23) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: c=IN IP4 63.79.178.4 (20) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:4559 parse_request: Line: a=ptime:20 (10) [Jan 9 14:27:38] --- (15 headers 9 lines) --- [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:2053 __sip_ack: Acked pending invite 102 [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80' of Request 102: Match Not Found [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:11531 handle_response_invite: SIP response 200 to standard invite [Jan 9 14:27:38] Found RTP audio format 8 [Jan 9 14:27:38] Peer audio RTP is at port 63.79.178.4:17938 [Jan 9 14:27:38] Found description format PCMA for ID 8 [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:5068 process_sdp: T38 state changed to 0 on channel SIP/leg2verizon-08a42860 [Jan 9 14:27:38] Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Jan 9 14:27:38] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jan 9 14:27:38] Peer audio RTP is at port 63.79.178.4:17938 [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:5145 process_sdp: We're settling with these formats: 0x8 (alaw) [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:5152 process_sdp: We have an owner, now see if we need to change this call [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Jan 9 14:27:38] DEBUG[8858]: chan_sip.c:7862 build_route: build_route: Record-Route hop: [Jan 9 14:27:38] list_route: hop: [Jan 9 14:27:38] set_destination: Parsing for address/port to send to [Jan 9 14:27:38] set_destination: set destination to 63.79.178.194, port 5060 [Jan 9 14:27:38] Transmitting (no NAT) to 63.79.178.194:5060: ACK sip:333010814012703950@63.79.178.4:5060 SIP/2.0 Via: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK633d0e71;rport Route: From: "8667674187" ;tag=as1ed0d396 To: ;tag=A20F71DC-1BBC Contact: Call-ID: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Jan 9 14:27:38] DEBUG[8881]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/leg2verizon-08a42860 [Jan 9 14:27:38] -- SIP/leg2verizon-08a42860 answered Local/333@clixme_initiate_call-316e,1 [Jan 9 14:27:38] DEBUG[8881]: rtp.c:1457 ast_rtp_early_bridge: Channel 'Local/333@clixme_initiate_call-316e,1' has no RTP, not doing anything [Jan 9 14:27:38] DEBUG[8854]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - leg2verizon [Jan 9 14:27:38] DEBUG[8854]: chan_sip.c:15048 sip_devicestate: Checking device state for peer leg2verizon [Jan 9 14:27:38] DEBUG[8854]: devicestate.c:287 do_state_change: Changing state for SIP/leg2verizon - state 1 (Not in use) [Jan 9 14:27:38] DEBUG[8891]: app_queue.c:546 changethread: Device 'SIP/leg2verizon' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 9 14:27:38] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:41] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:42] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:45] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:45] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:48] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:52] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:52] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:56] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:27:57] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:28:01] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:28:01] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:28:05] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:28:05] DEBUG[8877]: pbx_spool.c:390 scan_service: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/1168370824.outgoing' [Jan 9 14:28:06] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:28:11] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:28:12] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:28:13] DEBUG[8866]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/616 [Jan 9 14:28:13] DEBUG[8854]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 616 [Jan 9 14:28:13] DEBUG[8854]: chan_iax2.c:9600 iax2_devicestate: Checking device state for device 616 [Jan 9 14:28:13] DEBUG[8854]: chan_iax2.c:9608 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 616? addr=50374848, defaddr=0 maxms=0, lastms=0 [Jan 9 14:28:13] DEBUG[8854]: devicestate.c:287 do_state_change: Changing state for IAX2/616 - state 1 (Not in use) [Jan 9 14:28:13] DEBUG[8892]: app_queue.c:546 changethread: Device 'IAX2/616' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 9 14:28:15] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:28:16] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:28:21] DEBUG[8882]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:28:22] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 9 14:28:26] DEBUG[8881]: rtp.c:862 ast_rtcp_read: Got RTCP report of 68 bytes [Jan 9 14:28:26] <--- SIP read from 63.79.178.194:5060 ---> BYE sip:8667674187@63.118.244.80:5060 SIP/2.0 v: SIP/2.0/UDP 63.79.178.194:5060;branch=z9hG4bKcc91ccdfaa7877802c5afb0a16bf595b.24d7b5d0 v: SIP/2.0/UDP 63.79.178.4:5060;branch=z9hG4bK1E52;received=63.79.178.4 f: ;tag=A20F71DC-1BBC t: "8667674187" ;tag=as1ed0d396 Date: Tue, 09 Jan 2007 19:22:24 GMT i: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 User-Agent: Cisco-SIPGateway/IOS-12.x Max-Forwards: 5 Timestamp: 1168370591 CSeq: 101 BYE l: 0 <-------------> [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 0: BYE sip:8667674187@63.118.244.80:5060 SIP/2.0 (45) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 1: v: SIP/2.0/UDP 63.79.178.194:5060;branch=z9hG4bKcc91ccdfaa7877802c5afb0a16bf595b.24d7b5d0 (89) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 2: v: SIP/2.0/UDP 63.79.178.4:5060;branch=z9hG4bK1E52;received=63.79.178.4 (71) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 3: f: ;tag=A20F71DC-1BBC (53) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 4: t: "8667674187" ;tag=as1ed0d396 (61) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 5: Date: Tue, 09 Jan 2007 19:22:24 GMT (35) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 6: i: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 (49) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 7: User-Agent: Cisco-SIPGateway/IOS-12.x (37) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 8: Max-Forwards: 5 (15) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 9: Timestamp: 1168370591 (21) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 10: CSeq: 101 BYE (13) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 11: l: 0 (4) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 12: (0) [Jan 9 14:28:26] --- (12 headers 0 lines) --- [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:14453 handle_request: **** Received BYE (8) - Command in SIP BYE [Jan 9 14:28:26] Sending to 63.79.178.194 : 5060 (no NAT) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:1615 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:14030 handle_request_bye: Received bye, issuing owner hangup .[Jan 9 14:28:26] <--- Transmitting (no NAT) to 63.79.178.194:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 63.79.178.194:5060;branch=z9hG4bKcc91ccdfaa7877802c5afb0a16bf595b.24d7b5d0;received=63.79.178.194 Via: SIP/2.0/UDP 63.79.178.4:5060;branch=z9hG4bK1E52;received=63.79.178.4 From: ;tag=A20F71DC-1BBC To: "8667674187" ;tag=as1ed0d396 Call-ID: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 CSeq: 101 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 9 14:28:26] DEBUG[8881]: channel.c:3682 ast_generic_bridge: Didn't get a frame from channel: SIP/leg2verizon-08a42860 [Jan 9 14:28:26] DEBUG[8881]: channel.c:3990 ast_channel_bridge: Bridge stops bridging channels Local/333@clixme_initiate_call-316e,1 and SIP/leg2verizon-08a42860 [Jan 9 14:28:26] DEBUG[8881]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/leg2verizon-08a42860' [Jan 9 14:28:26] DEBUG[8881]: chan_sip.c:3278 sip_hangup: Hangup call SIP/leg2verizon-08a42860, SIP callid 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80) [Jan 9 14:28:26] DEBUG[8881]: chan_sip.c:3286 sip_hangup: update_call_counter(+14012703950) - decrement call limit counter on hangup [Jan 9 14:28:26] DEBUG[8881]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Jan 9 14:28:26] DEBUG[8881]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/leg2verizon-08a42860 [Jan 9 14:28:26] DEBUG[8881]: rtp.c:1457 ast_rtp_early_bridge: Channel 'Local/333@clixme_initiate_call-316e,1' has no RTP, not doing anything [Jan 9 14:28:26] DEBUG[8881]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jan 9 14:28:26] DEBUG[8881]: pbx.c:2363 __ast_pbx_run: Spawn extension (clixme_initiate_call,4012703950,26) exited non-zero on 'Local/333@clixme_initiate_call-316e,1' [Jan 9 14:28:26] == Spawn extension (clixme_initiate_call, 4012703950, 26) exited non-zero on 'Local/333@clixme_initiate_call-316e,1' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '4012703950' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '4012703950' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '4012703950' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'clixme_initiate_call' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Local/333@clixme_initiate_call-316e,1' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/leg2verizon-08a42860' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Dial' [Jan 9 14:28:26] DEBUG[8854]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - leg2verizon [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/+14012703950@leg2verizon|90' [Jan 9 14:28:26] DEBUG[8854]: chan_sip.c:15048 sip_devicestate: Checking device state for peer leg2verizon [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-01-09 14:27:30' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-01-09 14:28:26' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '56' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '0' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1168370824.0' [Jan 9 14:28:26] DEBUG[8881]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Jan 9 14:28:26] DEBUG[8881]: channel.c:1606 ast_hangup: Hanging up channel 'Local/333@clixme_initiate_call-316e,1' [Jan 9 14:28:26] DEBUG[8882]: channel.c:3682 ast_generic_bridge: Didn't get a frame from channel: Local/333@clixme_initiate_call-316e,2 [Jan 9 14:28:26] DEBUG[8881]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/333@clixme_initiate_call-316e,1 [Jan 9 14:28:26] Really destroying SIP dialog '64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80' Method: BYE [Jan 9 14:28:26] DEBUG[8854]: devicestate.c:287 do_state_change: Changing state for SIP/leg2verizon - state 1 (Not in use) [Jan 9 14:28:26] NOTICE[8881]: pbx_spool.c:351 attempt_thread: Call completed to Local/333@clixme_initiate_call/n [Jan 9 14:28:26] DEBUG[8882]: channel.c:3990 ast_channel_bridge: Bridge stops bridging channels Local/333@clixme_initiate_call-316e,2 and SIP/verizon-08a34868 [Jan 9 14:28:26] DEBUG[8854]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 333@clixme_initiate_call [Jan 9 14:28:26] DEBUG[8882]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/verizon-08a34868' [Jan 9 14:28:26] DEBUG[8854]: chan_local.c:145 local_devicestate: Checking if extension 333@clixme_initiate_call exists (devicestate) [Jan 9 14:28:26] DEBUG[8882]: chan_sip.c:3278 sip_hangup: Hangup call SIP/verizon-08a34868, SIP callid 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80) [Jan 9 14:28:26] DEBUG[8854]: devicestate.c:287 do_state_change: Changing state for Local/333@clixme_initiate_call - state 2 (In use) [Jan 9 14:28:26] DEBUG[8882]: chan_sip.c:3286 sip_hangup: update_call_counter(14016411072) - decrement call limit counter on hangup [Jan 9 14:28:26] DEBUG[8893]: app_queue.c:546 changethread: Device 'SIP/leg2verizon' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 9 14:28:26] DEBUG[8894]: app_queue.c:546 changethread: Device 'Local/333@clixme_initiate_call' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 9 14:28:26] DEBUG[8882]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Jan 9 14:28:26] Scheduling destruction of SIP dialog '0ea3e4236ddd388235379c0c7a646b58@63.118.244.80' in 32000 ms (Method: INVITE) [Jan 9 14:28:26] set_destination: Parsing for address/port to send to [Jan 9 14:28:26] set_destination: set destination to 63.79.178.192, port 5060 [Jan 9 14:28:26] Reliably Transmitting (no NAT) to 63.79.178.192:5060: BYE sip:333010814016411072@63.79.178.4:5060 SIP/2.0 Via: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK1e9a00c2;rport Route: From: "4012703950" ;tag=as5077fa0c To: ;tag=A20F0D18-19F4 Call-ID: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Jan 9 14:28:26] DEBUG[8882]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #14 [Jan 9 14:28:26] DEBUG[8882]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/verizon-08a34868 [Jan 9 14:28:26] DEBUG[8882]: rtp.c:1457 ast_rtp_early_bridge: Channel 'Local/333@clixme_initiate_call-316e,2' has no RTP, not doing anything [Jan 9 14:28:26] DEBUG[8882]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jan 9 14:28:26] DEBUG[8854]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - verizon [Jan 9 14:28:26] DEBUG[8854]: chan_sip.c:15048 sip_devicestate: Checking device state for peer verizon [Jan 9 14:28:26] DEBUG[8854]: devicestate.c:287 do_state_change: Changing state for SIP/verizon - state 1 (Not in use) [Jan 9 14:28:26] DEBUG[8895]: app_queue.c:546 changethread: Device 'SIP/verizon' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 9 14:28:26] -- AGI Script Executing Application: (Set) Options: (VEND_RESP=1) [Jan 9 14:28:26] -- AGI Script Executing Application: (Set) Options: (VENDOR_BUSY=0) [Jan 9 14:28:26] -- AGI Script Executing Application: (Set) Options: (SEND_WEBOWNER_MAIL=) [Jan 9 14:28:26] -- AGI Script Executing Application: (Set) Options: (SEND_WEBOWNER_MAIL2=) [Jan 9 14:28:26] -- AGI Script PrepaidCallClixme completed, returning 0 [Jan 9 14:28:26] DEBUG[8882]: pbx.c:2383 __ast_pbx_run: Extension 1, priority 7 returned normally even though call was hung up [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'DeadAGI' [Jan 9 14:28:26] -- Executing [h@clixme_agi:1] DeadAGI("Local/333@clixme_initiate_call-316e,2", "PrepaidFinalizeCallClixme") in new stack [Jan 9 14:28:26] -- Launched AGI Script /var/lib/asterisk/agi-bin/PrepaidFinalizeCallClixme [Jan 9 14:28:26] -- AGI Script Executing Application: (Set) Options: (CHARGE_FOR_NO_ANSWER=0) [Jan 9 14:28:26] -- AGI Script Executing Application: (Set) Options: (VENDOR_BUSY=0) [Jan 9 14:28:26] -- AGI Script Executing Application: (SetGlobalVar) Options: (CUST_BUSY_316e=0) [Jan 9 14:28:26] == Setting global variable 'CUST_BUSY_316e' to '0' [Jan 9 14:28:26] -- AGI Script Executing Application: (Set) Options: (rate_per_minute=0) [Jan 9 14:28:26] -- AGI Script Executing Application: (Set) Options: (first_minute_rate=0) [Jan 9 14:28:26] -- AGI Script Executing Application: (Set) Options: (ANSWEREDTIME=0) [Jan 9 14:28:26] -- AGI Script Executing Application: (Set) Options: (GO_AUTORECHARGE=0) [Jan 9 14:28:26] <--- SIP read from 63.79.178.192:5060 ---> SIP/2.0 200 OK v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK1e9a00c2;rport;received=63.118.244.80 f: "4012703950" ;tag=as5077fa0c t: ;tag=A20F0D18-19F4 Date: Tue, 09 Jan 2007 19:23:11 GMT i: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 Server: Cisco-SIPGateway/IOS-12.x l: 0 CSeq: 103 BYE <-------------> [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 1: v: SIP/2.0/UDP 63.118.244.80:5060;branch=z9hG4bK1e9a00c2;rport;received=63.118.244.80 (85) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 2: f: "4012703950" ;tag=as5077fa0c (61) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 3: t: ;tag=A20F0D18-19F4 (52) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 4: Date: Tue, 09 Jan 2007 19:23:11 GMT (35) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 5: i: 0ea3e4236ddd388235379c0c7a646b58@63.118.244.80 (49) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 7: l: 0 (4) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 8: CSeq: 103 BYE (13) [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 9: (0) [Jan 9 14:28:26] --- (9 headers 0 lines) --- [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:2061 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #14 [Jan 9 14:28:26] DEBUG[8858]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '0ea3e4236ddd388235379c0c7a646b58@63.118.244.80' of Request 103: Match Not Found [Jan 9 14:28:26] Really destroying SIP dialog '0ea3e4236ddd388235379c0c7a646b58@63.118.244.80' Method: INVITE [Jan 9 14:28:26] -- AGI Script PrepaidFinalizeCallClixme completed, returning 0 [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:28:26] -- Executing [h@clixme_agi:2] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?SendRequest:EmailTest") in new stack [Jan 9 14:28:26] -- Goto (clixme_agi,h,5) [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:28:26] -- Executing [h@clixme_agi:5] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?SendEmail:TryEmail2") in new stack [Jan 9 14:28:26] -- Goto (clixme_agi,h,8) [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:28:26] -- Executing [h@clixme_agi:8] GotoIf("Local/333@clixme_initiate_call-316e,2", "0?SendEmail2:AnnounceGuestTest") in new stack [Jan 9 14:28:26] -- Goto (clixme_agi,h,11) [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '1' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' [Jan 9 14:28:26] -- Executing [h@clixme_agi:11] GotoIf("Local/333@clixme_initiate_call-316e,2", "1?FinalHang:AnnounceGuest") in new stack [Jan 9 14:28:26] -- Goto (clixme_agi,h,28) [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1767 pbx_extension_helper: Launching 'Hangup' [Jan 9 14:28:26] -- Executing [h@clixme_agi:28] Hangup("Local/333@clixme_initiate_call-316e,2", "") in new stack [Jan 9 14:28:26] DEBUG[8882]: pbx.c:2483 __ast_pbx_run: Spawn extension (clixme_agi,h,28) exited non-zero on 'Local/333@clixme_initiate_call-316e,2' [Jan 9 14:28:26] == Spawn extension (clixme_agi, h, 28) exited non-zero on 'Local/333@clixme_initiate_call-316e,2' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '4012703950' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '4012703950' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'h' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'clixme_agi' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Local/333@clixme_initiate_call-316e,2' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/verizon-08a34868' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Hangup' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-01-09 14:27:04' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-01-09 14:27:30' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-01-09 14:28:26' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '82' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '56' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1168370824.1' [Jan 9 14:28:26] DEBUG[8882]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Jan 9 14:28:26] DEBUG[8882]: channel.c:1606 ast_hangup: Hanging up channel 'Local/333@clixme_initiate_call-316e,2' [Jan 9 14:28:26] DEBUG[8882]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/333@clixme_initiate_call-316e,2 [Jan 9 14:28:26] DEBUG[8854]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 333@clixme_initiate_call [Jan 9 14:28:26] DEBUG[8854]: chan_local.c:145 local_devicestate: Checking if extension 333@clixme_initiate_call exists (devicestate) [Jan 9 14:28:26] DEBUG[8854]: devicestate.c:287 do_state_change: Changing state for Local/333@clixme_initiate_call - state 1 (Not in use) [Jan 9 14:28:26] DEBUG[8897]: app_queue.c:546 changethread: Device 'Local/333@clixme_initiate_call' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 9 14:28:27] <--- SIP read from 63.79.178.194:5060 ---> BYE sip:8667674187@63.118.244.80:5060 SIP/2.0 v: SIP/2.0/UDP 63.79.178.194:5060;branch=z9hG4bKcc91ccdfaa7877802c5afb0a16bf595b.24d7b5d0 v: SIP/2.0/UDP 63.79.178.4:5060;branch=z9hG4bK1E52;received=63.79.178.4 f: ;tag=A20F71DC-1BBC t: "8667674187" ;tag=as1ed0d396 Date: Tue, 09 Jan 2007 19:22:24 GMT i: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 User-Agent: Cisco-SIPGateway/IOS-12.x Max-Forwards: 5 Timestamp: 1168370591 CSeq: 101 BYE l: 0 <-------------> [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 0: BYE sip:8667674187@63.118.244.80:5060 SIP/2.0 (45) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 1: v: SIP/2.0/UDP 63.79.178.194:5060;branch=z9hG4bKcc91ccdfaa7877802c5afb0a16bf595b.24d7b5d0 (89) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 2: v: SIP/2.0/UDP 63.79.178.4:5060;branch=z9hG4bK1E52;received=63.79.178.4 (71) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 3: f: ;tag=A20F71DC-1BBC (53) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 4: t: "8667674187" ;tag=as1ed0d396 (61) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 5: Date: Tue, 09 Jan 2007 19:22:24 GMT (35) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 6: i: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 (49) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 7: User-Agent: Cisco-SIPGateway/IOS-12.x (37) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 8: Max-Forwards: 5 (15) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 9: Timestamp: 1168370591 (21) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 10: CSeq: 101 BYE (13) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 11: l: 0 (4) [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:4527 parse_request: Header 12: (0) [Jan 9 14:28:27] --- (12 headers 0 lines) --- [Jan 9 14:28:27] <--- Transmitting (no NAT) to 63.79.178.194:5060 ---> SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/UDP 63.79.178.194:5060;branch=z9hG4bKcc91ccdfaa7877802c5afb0a16bf595b.24d7b5d0;received=63.79.178.194 Via: SIP/2.0/UDP 63.79.178.4:5060;branch=z9hG4bK1E52;received=63.79.178.4 From: ;tag=A20F71DC-1BBC To: "8667674187" ;tag=as1ed0d396 Call-ID: 64e149af1b6d6c9a3050f5d3545510b3@63.118.244.80 CSeq: 101 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Jan 9 14:28:27] DEBUG[8858]: chan_sip.c:14631 sipsock_read: Invalid SIP message - rejected , no callid, len 519 *CLI> exit No such command 'exit' (type 'help' for help) *CLI>