[Nov 17 08:59:13] Asterisk Ready. ]1;Asterisk]2;Asterisk Console on 'fudd' (pid 19046)*CLI> sip debug SIP Debugging enabled *CLI> [Nov 17 08:59:21] DEBUG[19066]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19066]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '1' [Nov 17 08:59:21] DEBUG[19066]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19066]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '1' [Nov 17 08:59:21] -- Accepting AUTHENTICATED call from 64.94.196.24: > requested format = ulaw, > requested prefs = (), > actual format = ulaw, > host prefs = (g729|ulaw), > priority = mine [Nov 17 08:59:21] DEBUG[19051]: chan_iax2.c:9327 iax2_devicestate: Checking device state for device tweety [Nov 17 08:59:21] DEBUG[19051]: chan_iax2.c:9335 iax2_devicestate: iax2_devicestate(tweety): Found peer. What's device state of tweety? addr=415522368, defaddr=0 maxms=2000, lastms=1 [Nov 17 08:59:21] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for IAX2/tweety - state 2 (In use) [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19073]: app_queue.c:471 changethread: Device 'IAX2/tweety' changed to state '2' (In use) [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '1' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '1' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '1' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '1' [Nov 17 08:59:21] -- Executing macro("IAX2/tweety-3", "exttest_callblock|4846841088") [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'macro-exttest_callblock' AND priority = '1' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'macro-exttest_callblock' AND priority = '1' ORDER BY exten [Nov 17 08:59:21] WARNING[19072]: app_macro.c:151 macro_exec: Context 'macro-exttest_callblock' for macro 'exttest_callblock' lacks 's' extension, priority 1 [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '2' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '2' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '2' [Nov 17 08:59:21] -- Executing macro("IAX2/tweety-3", "pathvalidate|exttest|2|inbound") [Nov 17 08:59:21] DEBUG[19072]: pbx.c:1674 pbx_extension_helper: Launching 'Set' [Nov 17 08:59:21] -- Executing Set("IAX2/tweety-3", "GROUP()=exttest") in new stack [Nov 17 08:59:21] DEBUG[19072]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '1' [Nov 17 08:59:21] DEBUG[19072]: pbx.c:1586 pbx_substitute_variables_helper_full: Expression result is '0' [Nov 17 08:59:21] DEBUG[19072]: pbx.c:1674 pbx_extension_helper: Launching 'GotoIf' [Nov 17 08:59:21] -- Executing GotoIf("IAX2/tweety-3", "0?inbound_path_exceeded|s|1") in new stack [Nov 17 08:59:21] DEBUG[19072]: pbx.c:6171 pbx_builtin_gotoif: Not taking any branch [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '3' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '3' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '4846841088' AND context = 'did_routes_in' AND priority = '3' [Nov 17 08:59:21] -- Executing GoTo("IAX2/tweety-3", "exttest_main_1|s|1") [Nov 17 08:59:21] -- Goto (exttest_main_1,s,1) [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'exttest_main_1' AND priority = '1' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'exttest_main_1' AND priority = '1' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'exttest_main_1' AND priority = '1' [Nov 17 08:59:21] -- Executing goto("IAX2/tweety-3", "exttest_custom_fastech|s|1") [Nov 17 08:59:21] -- Goto (exttest_custom_fastech,s,1) [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'exttest_custom_fastech' AND priority = '1' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'exttest_custom_fastech' AND priority = '1' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'exttest_custom_fastech' AND priority = '1' [Nov 17 08:59:21] -- Executing goto("IAX2/tweety-3", "fastech_custom_QUEUE_UST|s|1") [Nov 17 08:59:21] -- Goto (fastech_custom_QUEUE_UST,s,1) [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'fastech_custom_QUEUE_UST' AND priority = '1' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'fastech_custom_QUEUE_UST' AND priority = '1' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'fastech_custom_QUEUE_UST' AND priority = '1' [Nov 17 08:59:21] -- Executing SET("IAX2/tweety-3", "CALLERID(name)=UST") [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'fastech_custom_QUEUE_UST' AND priority = '2' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'fastech_custom_QUEUE_UST' AND priority = '2' [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:21] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'fastech_custom_QUEUE_UST' AND priority = '2' [Nov 17 08:59:21] -- Executing Playback("IAX2/tweety-3", "/var/spool/asterisk/voicemail/fastech/1016/unavail") [Nov 17 08:59:21] DEBUG[19072]: chan_iax2.c:3337 iax2_answer: Answering IAX2 call [Nov 17 08:59:21] DEBUG[19051]: chan_iax2.c:9327 iax2_devicestate: Checking device state for device tweety [Nov 17 08:59:21] DEBUG[19051]: chan_iax2.c:9335 iax2_devicestate: iax2_devicestate(tweety): Found peer. What's device state of tweety? addr=415522368, defaddr=0 maxms=2000, lastms=1 [Nov 17 08:59:21] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for IAX2/tweety - state 2 (In use) [Nov 17 08:59:21] DEBUG[19074]: app_queue.c:471 changethread: Device 'IAX2/tweety' changed to state '2' (In use) [Nov 17 08:59:21] DEBUG[19072]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to write format slin [Nov 17 08:59:21] DEBUG[19072]: channel.c:1711 ast_settimeout: Scheduling timer at 160 sample intervals [Nov 17 08:59:21] -- Playing '/var/spool/asterisk/voicemail/fastech/1016/unavail' (language 'en') [Nov 17 08:59:21] DEBUG[19066]: chan_iax2.c:6670 socket_read: Ooh, voice format changed to 4 [Nov 17 08:59:21] DEBUG[19066]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to read format ulaw [Nov 17 08:59:23] DEBUG[19072]: channel.c:1711 ast_settimeout: Scheduling timer at 138 sample intervals [Nov 17 08:59:23] DEBUG[19072]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals [Nov 17 08:59:23] DEBUG[19072]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals [Nov 17 08:59:23] DEBUG[19072]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to write format ulaw [Nov 17 08:59:23] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'fastech_custom_QUEUE_UST' AND priority = '3' [Nov 17 08:59:23] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'fastech_custom_QUEUE_UST' AND priority = '3' [Nov 17 08:59:23] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 's' AND context = 'fastech_custom_QUEUE_UST' AND priority = '3' [Nov 17 08:59:23] -- Executing Queue("IAX2/tweety-3", "fastech_UST|TtwW||") [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2921 queue_exec: NO QUEUE_PRIO variable found. Using default. [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2929 queue_exec: queue: fastech_UST, options: TtwW, url: , announce: , expires: 0, priority: 0 [Nov 17 08:59:23] DEBUG[19072]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to write format slin [Nov 17 08:59:23] -- Started music on hold, class 'default', on channel 'IAX2/tweety-3' [Nov 17 08:59:23] DEBUG[19072]: channel.c:1711 ast_settimeout: Scheduling timer at 160 sample intervals [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:1873 is_our_turn: It's our turn (IAX2/tweety-3). [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2070 try_calling: IAX2/tweety-3 is trying to call a queue member. [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2092 try_calling: Queue with URL=_ [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2092 try_calling: Queue with URL=_ [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2092 try_calling: Queue with URL=_ [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2092 try_calling: Queue with URL=_ [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2092 try_calling: Queue with URL=_ [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2092 try_calling: Queue with URL=_ [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2092 try_calling: Queue with URL=_ [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2092 try_calling: Queue with URL=_ [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2092 try_calling: Queue with URL=_ [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2092 try_calling: Queue with URL=_ [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:2092 try_calling: Queue with URL=_ [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:1495 ring_one: Trying 'Agent/8611' with metric 0 [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:1495 ring_one: Trying 'Agent/8610' with metric 0 [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:1495 ring_one: Trying 'Agent/5817' with metric 0 [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:1495 ring_one: Trying 'Agent/5925' with metric 0 [Nov 17 08:59:23] DEBUG[19072]: app_queue.c:1495 ring_one: Trying 'Agent/5842' with metric 0 [Nov 17 08:59:23] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5842' AND context = 'fastech_custom_Q_EXT' AND priority = '1' [Nov 17 08:59:23] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19072]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'fastech_custom_Q_EXT' AND priority = '1' ORDER BY exten [Nov 17 08:59:23] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for Local/5842@fastech_custom_Q_EXT - state 2 (In use) [Nov 17 08:59:23] DEBUG[19072]: channel.c:2813 ast_channel_inherit_variables: Not copying variable PLAYBACKSTATUS. [Nov 17 08:59:23] DEBUG[19072]: channel.c:2813 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Nov 17 08:59:23] DEBUG[19072]: channel.c:2813 ast_channel_inherit_variables: Not copying variable STACK-macro-pathvalidate-s-2. [Nov 17 08:59:23] DEBUG[19072]: channel.c:2813 ast_channel_inherit_variables: Not copying variable GROUP. [Nov 17 08:59:23] DEBUG[19072]: channel.c:2813 ast_channel_inherit_variables: Not copying variable STACK-macro-pathvalidate-s-1. [Nov 17 08:59:23] -- outgoing agentcall, to agent '5842', on 'Local/5842@fastech_custom_Q_EXT-6ba2,1' [Nov 17 08:59:23] DEBUG[19075]: app_queue.c:471 changethread: Device 'Local/5842@fastech_custom_Q_EXT' changed to state '2' (In use) [Nov 17 08:59:23] -- Called Agent/5842 [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5842' AND context = 'fastech_custom_Q_EXT' AND priority = '1' [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'fastech_custom_Q_EXT' AND priority = '1' ORDER BY exten [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5842' AND context = 'fastech_custom_Q_EXT' AND priority = '1' [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'fastech_custom_Q_EXT' AND priority = '1' ORDER BY exten [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5842' AND context = 'fastech_custom_Q_EXT' AND priority = '1' [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'fastech_custom_Q_EXT' AND priority = '1' ORDER BY exten [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5842' AND context = 'fastech_custom_Q_EXT' AND priority = '1' [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'fastech_custom_Q_EXT' AND priority = '1' ORDER BY exten [Nov 17 08:59:23] -- Executing Dial("Local/5842@fastech_custom_Q_EXT-6ba2,2", "SIP/sip5842_fastech|20|tm") [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3121 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = 'sip5842_fastech' [Nov 17 08:59:23] -- SIP Seeding peer from astdb: 'sip5842_fastech' at sip5842_fastech@64.94.197.130:13644 for 3600 [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:1867 create_addr_from_peer: Setting NAT on RTP to 524288 [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:2061 sip_call: Outgoing Call for sip5842_fastech [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:2202 update_call_counter: Updating call counter for outgoing call [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3121 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Nov 17 08:59:23] We're at 64.94.196.22 port 14570 [Nov 17 08:59:23] Adding codec 0x4 (ulaw) to SDP [Nov 17 08:59:23] Adding codec 0x100 (g729) to SDP [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: NOTIFY sip:sip5842_fastech@172.16.3.50 SIP/2.0 (46) [Nov 17 08:59:23] Adding codec 0x8 (alaw) to SDP [Nov 17 08:59:23] Adding non-codec 0x1 (telephone-event) to SDP [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK1a30dd5f;rport (63) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "NOCALLERID" ;tag=as630e7e51 (63) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: (37) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: Contact: (38) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 6585447d4c03786e159a3c3422cc8328@64.94.196.22 (54) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: CoreDialPBX (23) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Max-Forwards: 70 (16) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Event: message-summary (22) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 11: Content-Length: 92 (18) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 12: (0) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: Messages-Waiting: no (20) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: Message-Account: sip:asterisk@64.94.196.22 (42) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 0: INVITE sip:sip5842_fastech@172.16.3.50 SIP/2.0 (46) [Nov 17 08:59:23] 12 headers, 3 lines [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK37fe7c3b;rport (63) [Nov 17 08:59:23] Reliably Transmitting (NAT) to 64.94.197.130:13644: NOTIFY sip:sip5842_fastech@172.16.3.50 SIP/2.0 Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK1a30dd5f;rport From: "NOCALLERID" ;tag=as630e7e51 To: Contact: Call-ID: 6585447d4c03786e159a3c3422cc8328@64.94.196.22 CSeq: 102 NOTIFY User-Agent: CoreDialPBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 92 Messages-Waiting: no Message-Account: sip:asterisk@64.94.196.22 Voice-Message: 0/0 (0/0) --- [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 2: From: "UST" ;tag=as653a71a7 (56) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 3: To: (37) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 4: Contact: (38) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (54) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 6: CSeq: 102 INVITE (16) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:1286 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #2 [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 7: User-Agent: CoreDialPBX (23) [Nov 17 08:59:23] Scheduling destruction of call '6585447d4c03786e159a3c3422cc8328@64.94.196.22' in 15000 ms [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 8: Max-Forwards: 70 (16) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 9: Date: Fri, 17 Nov 2006 13:59:23 GMT (35) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 11: Content-Type: application/sdp (29) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 12: Content-Length: 287 (19) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3337 parse_request: Header 13: (0) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: v=0 (3) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: o=root 19046 19046 IN IP4 64.94.196.22 (38) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: s=session (9) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: c=IN IP4 64.94.196.22 (21) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: t=0 0 (5) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: m=audio 14570 RTP/AVP 0 18 8 101 (32) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: a=fmtp:18 annexb=no (19) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: a=fmtp:101 0-16 (15) [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:3369 parse_request: Line: a=silenceSupp:off - - - - (25) [Nov 17 08:59:23] 13 headers, 13 lines [Nov 17 08:59:23] Reliably Transmitting (NAT) to 64.94.197.130:13644: INVITE sip:sip5842_fastech@172.16.3.50 SIP/2.0 Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK37fe7c3b;rport From: "UST" ;tag=as653a71a7 To: Contact: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 CSeq: 102 INVITE User-Agent: CoreDialPBX Max-Forwards: 70 Date: Fri, 17 Nov 2006 13:59:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 287 v=0 o=root 19046 19046 IN IP4 64.94.196.22 s=session c=IN IP4 64.94.196.22 t=0 0 m=audio 14570 RTP/AVP 0 18 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- [Nov 17 08:59:23] DEBUG[19076]: chan_sip.c:1286 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #4 [Nov 17 08:59:23] -- Called sip5842_fastech [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5842' AND context = 'fastech_custom_Q_EXT' AND priority = '-1' [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:23] DEBUG[19076]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'fastech_custom_Q_EXT' AND priority = '-1' ORDER BY exten [Nov 17 08:59:23] DEBUG[19076]: channel.c:2165 ast_prod: Prodding channel 'Local/5842@fastech_custom_Q_EXT-6ba2,2' [Nov 17 08:59:23] DEBUG[19076]: channel.c:2348 set_format: Set channel Local/5842@fastech_custom_Q_EXT-6ba2,2 to write format slin [Nov 17 08:59:23] -- Started music on hold, class 'default', on channel 'Local/5842@fastech_custom_Q_EXT-6ba2,2' [Nov 17 08:59:23] DEBUG[19076]: channel.c:1711 ast_settimeout: Scheduling timer at 160 sample intervals [Nov 17 08:59:23] DEBUG[19072]: channel.c:1973 ast_read: Generator got voice, switching to phase locked mode [Nov 17 08:59:23] DEBUG[19072]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals [Nov 17 08:59:23] <-- SIP read from 64.94.197.130:13644: SIP/2.0 200 OK Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK1a30dd5f;rport From: "NOCALLERID" ;tag=as630e7e51 To: ;tag=115466E6-21D18417 CSeq: 102 NOTIFY Call-ID: 6585447d4c03786e159a3c3422cc8328@64.94.196.22 Contact: Event: message-summary User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Content-Length: 0 [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 200 OK (14) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK1a30dd5f;rport (63) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "NOCALLERID" ;tag=as630e7e51 (63) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=115466E6-21D18417 (59) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 102 NOTIFY (16) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 6585447d4c03786e159a3c3422cc8328@64.94.196.22 (54) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: Event: message-summary (22) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Content-Length: 0 (17) [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: (0) [Nov 17 08:59:23] --- (10 headers 0 lines)[Nov 17 08:59:23] --- [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 6585447d4c03786e159a3c3422cc8328@64.94.196.22 Their Tag Our tag: as630e7e51 [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:1383 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #2 [Nov 17 08:59:23] DEBUG[19064]: chan_sip.c:1394 __sip_ack: Stopping retransmission on '6585447d4c03786e159a3c3422cc8328@64.94.196.22' of Request 102: Match Found [Nov 17 08:59:23] Destroying call '6585447d4c03786e159a3c3422cc8328@64.94.196.22' [Nov 17 08:59:24] DEBUG[19064]: chan_sip.c:1177 retrans_pkt: SIP TIMER: Rescheduling retransmission #4 (1) INVITE - 5 [Nov 17 08:59:24] DEBUG[19064]: chan_sip.c:1191 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #4)) [Nov 17 08:59:24] Retransmitting #1 (NAT) to 64.94.197.130:13644: INVITE sip:sip5842_fastech@172.16.3.50 SIP/2.0 Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK37fe7c3b;rport From: "UST" ;tag=as653a71a7 To: Contact: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 CSeq: 102 INVITE User-Agent: CoreDialPBX Max-Forwards: 70 Date: Fri, 17 Nov 2006 13:59:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 287 v=0 o=root 19046 19046 IN IP4 64.94.196.22 s=session c=IN IP4 64.94.196.22 t=0 0 m=audio 14570 RTP/AVP 0 18 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- [Nov 17 08:59:25] <-- SIP read from 64.94.197.130:13644: SIP/2.0 100 Trying Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK37fe7c3b;rport From: "UST" ;tag=as653a71a7 To: ;tag=7D74B61B-98F74618 CSeq: 102 INVITE Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Content-Length: 0 [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 100 Trying (18) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK37fe7c3b;rport (63) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "UST" ;tag=as653a71a7 (56) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=7D74B61B-98F74618 (59) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 102 INVITE (16) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (54) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Content-Length: 0 (17) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: (0) [Nov 17 08:59:25] --- (9 headers 0 lines)[Nov 17 08:59:25] --- [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Their Tag Our tag: as653a71a7 [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:1438 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #4 - INVITE (got response) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:1447 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22' Request 102: Found [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:9459 handle_response_invite: SIP response 100 to standard invite [Nov 17 08:59:25] <-- SIP read from 64.94.197.130:13644: SIP/2.0 100 Trying Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK37fe7c3b;rport From: "UST" ;tag=as653a71a7 To: ;tag=7D74B61B-98F74618 CSeq: 102 INVITE Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Content-Length: 0 [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 100 Trying (18) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK37fe7c3b;rport (63) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "UST" ;tag=as653a71a7 (56) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=7D74B61B-98F74618 (59) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 102 INVITE (16) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (54) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Content-Length: 0 (17) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: (0) [Nov 17 08:59:25] --- (9 headers 0 lines)[Nov 17 08:59:25] --- [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Their Tag 7D74B61B-98F74618 Our tag: as653a71a7 [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:1447 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22' Request 102: Found [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:9459 handle_response_invite: SIP response 100 to standard invite [Nov 17 08:59:25] <-- SIP read from 64.94.197.130:13644: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK37fe7c3b;rport From: "UST" ;tag=as653a71a7 To: ;tag=7D74B61B-98F74618 CSeq: 102 INVITE Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Allow-Events: talk,hold,conference Content-Length: 0 [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK37fe7c3b;rport (63) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "UST" ;tag=as653a71a7 (56) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=7D74B61B-98F74618 (59) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 102 INVITE (16) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (54) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Allow-Events: talk,hold,conference (34) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Content-Length: 0 (17) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: (0) [Nov 17 08:59:25] --- (10 headers 0 lines)[Nov 17 08:59:25] --- [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Their Tag 7D74B61B-98F74618 Our tag: as653a71a7 [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:1447 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22' Request 102: Found [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:9459 handle_response_invite: SIP response 180 to standard invite [Nov 17 08:59:25] DEBUG[19051]: chan_sip.c:11502 sip_devicestate: Checking device state for peer sip5842_fastech [Nov 17 08:59:25] -- SIP/sip5842_fastech-3268 is ringing [Nov 17 08:59:25] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for SIP/sip5842_fastech - state 6 (Ringing) [Nov 17 08:59:25] DEBUG[19077]: app_queue.c:471 changethread: Device 'SIP/sip5842_fastech' changed to state '6' (Ringing) [Nov 17 08:59:25] <-- SIP read from 64.94.197.130:13644: SIP/2.0 200 OK Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK37fe7c3b;rport From: "UST" ;tag=as653a71a7 To: ;tag=7D74B61B-98F74618 CSeq: 102 INVITE Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Content-Type: application/sdp Content-Length: 185 v=0 o=- 1163771768 1163771768 IN IP4 172.16.3.50 s=Polycom IP Phone c=IN IP4 172.16.3.50 t=0 0 m=audio 2238 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 200 OK (14) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK37fe7c3b;rport (63) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "UST" ;tag=as653a71a7 (56) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=7D74B61B-98F74618 (59) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 102 INVITE (16) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (54) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Content-Type: application/sdp (29) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: Content-Length: 185 (19) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 11: (0) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: v=0 (3) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: o=- 1163771768 1163771768 IN IP4 172.16.3.50 (44) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: s=Polycom IP Phone (18) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: c=IN IP4 172.16.3.50 (20) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: t=0 0 (5) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: m=audio 2238 RTP/AVP 0 101 (26) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Nov 17 08:59:25] --- (11 headers 8 lines)[Nov 17 08:59:25] --- [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Their Tag 7D74B61B-98F74618 Our tag: as653a71a7 [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:1372 __sip_ack: Acked pending invite 102 [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:1394 __sip_ack: Stopping retransmission on '629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22' of Request 102: Match Found [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:9459 handle_response_invite: SIP response 200 to standard invite [Nov 17 08:59:25] Found RTP audio format 0 [Nov 17 08:59:25] Found RTP audio format 101 [Nov 17 08:59:25] Peer audio RTP is at port 172.16.3.50:2238 [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3521 process_sdp: Peer audio RTP is at port 172.16.3.50:2238 [Nov 17 08:59:25] Found description format PCMU [Nov 17 08:59:25] Found description format telephone-event [Nov 17 08:59:25] Capabilities: us - 0x10c (ulaw|alaw|g729), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Nov 17 08:59:25] Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:3618 process_sdp: Oooh, we need to change our formats since our peer supports only 0x4 (ulaw) and not 0x100 (g729) [Nov 17 08:59:25] DEBUG[19064]: channel.c:2348 set_format: Set channel SIP/sip5842_fastech-3268 to read format g729 [Nov 17 08:59:25] DEBUG[19064]: channel.c:2348 set_format: Set channel SIP/sip5842_fastech-3268 to write format g729 [Nov 17 08:59:25] DEBUG[19064]: chan_sip.c:6047 build_route: build_route: Contact hop: [Nov 17 08:59:25] list_route: hop: [Nov 17 08:59:25] set_destination: Parsing for address/port to send to [Nov 17 08:59:25] set_destination: set destination to 172.16.3.50, port 5060 [Nov 17 08:59:25] Transmitting (NAT) to 64.94.197.130:13644: ACK sip:sip5842_fastech@172.16.3.50 SIP/2.0 Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK19c973c6;rport From: "UST" ;tag=as653a71a7 To: ;tag=7D74B61B-98F74618 Contact: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 CSeq: 102 ACK User-Agent: CoreDialPBX Max-Forwards: 70 Content-Length: 0 --- [Nov 17 08:59:25] DEBUG[19051]: chan_sip.c:11502 sip_devicestate: Checking device state for peer sip5842_fastech [Nov 17 08:59:25] -- SIP/sip5842_fastech-3268 answered Local/5842@fastech_custom_Q_EXT-6ba2,2 [Nov 17 08:59:25] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for SIP/sip5842_fastech - state 2 (In use) [Nov 17 08:59:25] DEBUG[19076]: channel.c:2348 set_format: Set channel Local/5842@fastech_custom_Q_EXT-6ba2,2 to write format ulaw [Nov 17 08:59:25] -- Stopped music on hold on Local/5842@fastech_custom_Q_EXT-6ba2,2 [Nov 17 08:59:25] DEBUG[19078]: app_queue.c:471 changethread: Device 'SIP/sip5842_fastech' changed to state '2' (In use) [Nov 17 08:59:25] DEBUG[19076]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals [Nov 17 08:59:25] DEBUG[19076]: channel.c:2348 set_format: Set channel Local/5842@fastech_custom_Q_EXT-6ba2,2 to read format ulaw [Nov 17 08:59:25] DEBUG[19076]: channel.c:2348 set_format: Set channel SIP/sip5842_fastech-3268 to write format ulaw [Nov 17 08:59:25] DEBUG[19076]: channel.c:2348 set_format: Set channel SIP/sip5842_fastech-3268 to read format ulaw [Nov 17 08:59:25] DEBUG[19076]: channel.c:2348 set_format: Set channel Local/5842@fastech_custom_Q_EXT-6ba2,2 to write format ulaw [Nov 17 08:59:25] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for Local/5842@fastech_custom_Q_EXT - state 2 (In use) [Nov 17 08:59:25] -- Agent/5842 answered IAX2/tweety-3 [Nov 17 08:59:25] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for Local/5842@fastech_custom_Q_EXT - state 2 (In use) [Nov 17 08:59:25] DEBUG[19072]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to write format ulaw [Nov 17 08:59:25] -- Stopped music on hold on IAX2/tweety-3 [Nov 17 08:59:25] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for Agent/5842 - state 3 (Busy) [Nov 17 08:59:25] DEBUG[19072]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals [Nov 17 08:59:25] DEBUG[19079]: app_queue.c:471 changethread: Device 'Local/5842@fastech_custom_Q_EXT' changed to state '2' (In use) [Nov 17 08:59:25] DEBUG[19080]: app_queue.c:471 changethread: Device 'Local/5842@fastech_custom_Q_EXT' changed to state '2' (In use) [Nov 17 08:59:25] DEBUG[19081]: app_queue.c:471 changethread: Device 'Agent/5842' changed to state '3' (Busy) [Nov 17 08:59:25] DEBUG[19072]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to read format ulaw [Nov 17 08:59:25] DEBUG[19072]: channel.c:2348 set_format: Set channel Agent/5842 to write format ulaw [Nov 17 08:59:25] DEBUG[19072]: channel.c:2348 set_format: Set channel Agent/5842 to read format ulaw [Nov 17 08:59:25] DEBUG[19072]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to write format ulaw [Nov 17 08:59:25] DEBUG[19076]: rtp.c:1341 ast_rtp_write: Ooh, format changed from unknown to ulaw [Nov 17 08:59:26] -- Channel 'IAX2/tweety-3' unable to transfer [Nov 17 08:59:26] DEBUG[19076]: rtp.c:477 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 64.94.197.130:13846 [Nov 17 08:59:26] DEBUG[19076]: channel.c:2747 ast_channel_masquerade: Planning to masquerade channel SIP/sip5842_fastech-3268 into the structure of Local/5842@fastech_custom_Q_EXT-6ba2,1 [Nov 17 08:59:26] DEBUG[19076]: channel.c:2760 ast_channel_masquerade: Done planning to masquerade channel SIP/sip5842_fastech-3268 into the structure of Local/5842@fastech_custom_Q_EXT-6ba2,1 [Nov 17 08:59:26] DEBUG[19076]: chan_local.c:244 local_write: Not posting to queue since already masked on 'Local/5842@fastech_custom_Q_EXT-6ba2,2' [Nov 17 08:59:26] DEBUG[19072]: channel.c:2870 ast_do_masquerade: Actually Masquerading SIP/sip5842_fastech-3268(6) into the structure of Local/5842@fastech_custom_Q_EXT-6ba2,1(6) [Nov 17 08:59:26] DEBUG[19072]: channel.c:2881 ast_do_masquerade: Got clone lock for masquerade on 'SIP/sip5842_fastech-3268' at 0x85e4824 [Nov 17 08:59:26] DEBUG[19072]: channel.c:2348 set_format: Set channel SIP/sip5842_fastech-3268 to write format ulaw [Nov 17 08:59:26] DEBUG[19072]: channel.c:2348 set_format: Set channel SIP/sip5842_fastech-3268 to read format ulaw [Nov 17 08:59:26] DEBUG[19072]: channel.c:3042 ast_do_masquerade: Putting channel SIP/sip5842_fastech-3268 in 4/4 formats [Nov 17 08:59:26] DEBUG[19072]: channel.c:3077 ast_do_masquerade: Released clone lock on 'Local/5842@fastech_custom_Q_EXT-6ba2,1' [Nov 17 08:59:26] DEBUG[19076]: channel.c:3265 ast_generic_bridge: Didn't get a frame from channel: Local/5842@fastech_custom_Q_EXT-6ba2,2 [Nov 17 08:59:26] DEBUG[19072]: channel.c:3086 ast_do_masquerade: Done Masquerading SIP/sip5842_fastech-3268 (6) [Nov 17 08:59:26] DEBUG[19072]: chan_agent.c:547 agent_read: Bridge on 'SIP/sip5842_fastech-3268' being set to 'Agent/5842' (3) [Nov 17 08:59:26] DEBUG[19076]: channel.c:3540 ast_channel_bridge: Bridge stops bridging channels Local/5842@fastech_custom_Q_EXT-6ba2,2 and Local/5842@fastech_custom_Q_EXT-6ba2,1 [Nov 17 08:59:26] DEBUG[19076]: channel.c:1328 ast_hangup: Hanging up zombie 'Local/5842@fastech_custom_Q_EXT-6ba2,1' [Nov 17 08:59:26] DEBUG[19076]: app_dial.c:1605 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Nov 17 08:59:26] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for Local/5842@fastech_custom_Q_EXT - state 2 (In use) [Nov 17 08:59:26] DEBUG[19076]: pbx.c:2313 __ast_pbx_run: Spawn extension (fastech_custom_Q_EXT,5842,1) exited non-zero on 'Local/5842@fastech_custom_Q_EXT-6ba2,2' [Nov 17 08:59:26] DEBUG[19082]: app_queue.c:471 changethread: Device 'Local/5842@fastech_custom_Q_EXT' changed to state '2' (In use) [Nov 17 08:59:26] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:26] DEBUG[19076]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'h' AND context = 'fastech_custom_Q_EXT' AND priority = '1' [Nov 17 08:59:26] DEBUG[19076]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:26] DEBUG[19076]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'fastech_custom_Q_EXT' AND priority = '1' ORDER BY exten [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '"UST" <4847844300>' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '4847844300' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '5842' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'fastech_custom_Q_EXT' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'Local/5842@fastech_custom_Q_EXT-6ba2,2' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'SIP/sip5842_fastech-3268' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'Dial' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'SIP/sip5842_fastech|20|tm' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '2006-11-17 08:59:23' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '2006-11-17 08:59:25' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '2006-11-17 08:59:26' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '3' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '1' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '(null)' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '1163771963.2' [Nov 17 08:59:26] DEBUG[19076]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '(null)' [Nov 17 08:59:26] DEBUG[19076]: cdr_addon_mysql.c:207 mysql_log: cdr_mysql: inserting a CDR record. [Nov 17 08:59:26] DEBUG[19076]: cdr_addon_mysql.c:223 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2006-11-17 08:59:23','\"UST\" <4847844300>','4847844300','5842','fastech_custom_Q_EXT', 'Local/5842@fastech_custom_Q_EXT-6ba2,2','SIP/sip5842_fastech-3268','Dial','SIP/sip5842_fastech|20|tm',3,1,'ANSWERED',3,'','1163771963.2','') [Nov 17 08:59:26] DEBUG[19076]: channel.c:1323 ast_hangup: Hanging up channel 'Local/5842@fastech_custom_Q_EXT-6ba2,2' [Nov 17 08:59:26] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for Local/5842@fastech_custom_Q_EXT - state 0 (Unknown) [Nov 17 08:59:26] DEBUG[19083]: app_queue.c:471 changethread: Device 'Local/5842@fastech_custom_Q_EXT' changed to state '0' (Unknown) [Nov 17 08:59:28] <-- SIP read from 64.94.197.130:13644: INVITE sip:4847844300@64.94.196.22 SIP/2.0 Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bK236c55ba8D9D5CA5 From: ;tag=7D74B61B-98F74618 To: "UST" ;tag=as653a71a7 CSeq: 1 INVITE Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 181 v=0 o=- 1163771768 1163771769 IN IP4 172.16.3.50 s=Polycom IP Phone c=IN IP4 0.0.0.0 t=0 0 m=audio 2238 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: INVITE sip:4847844300@64.94.196.22 SIP/2.0 (42) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bK236c55ba8D9D5CA5 (59) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: ;tag=7D74B61B-98F74618 (61) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: "UST" ;tag=as653a71a7 (54) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 1 INVITE (14) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (54) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Supported: 100rel,replaces (26) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 11: Max-Forwards: 70 (16) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 12: Content-Type: application/sdp (29) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 13: Content-Length: 181 (19) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 14: (0) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: v=0 (3) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: o=- 1163771768 1163771769 IN IP4 172.16.3.50 (44) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: s=Polycom IP Phone (18) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: t=0 0 (5) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: m=audio 2238 RTP/AVP 0 101 (26) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Nov 17 08:59:28] --- (14 headers 8 lines)[Nov 17 08:59:28] --- [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Their Tag 7D74B61B-98F74618 Our tag: as653a71a7 [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:10980 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:997 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:1009 parse_sip_options: Found SIP option: -100rel- [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:1015 parse_sip_options: Matched SIP option: 100rel [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:1009 parse_sip_options: Found SIP option: -replaces- [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:1015 parse_sip_options: Matched SIP option: replaces [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:1026 parse_sip_options: * SIP extension value: 3 for call 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 [Nov 17 08:59:28] Using INVITE request as basis request - 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 [Nov 17 08:59:28] Sending to 172.16.3.50 : 5060 (NAT) [Nov 17 08:59:28] Found RTP audio format 0 [Nov 17 08:59:28] Found RTP audio format 101 [Nov 17 08:59:28] Peer audio RTP is at port 0.0.0.0:2238 [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3521 process_sdp: Peer audio RTP is at port 0.0.0.0:2238 [Nov 17 08:59:28] Found description format PCMU [Nov 17 08:59:28] Found description format telephone-event [Nov 17 08:59:28] Capabilities: us - 0x10c (ulaw|alaw|g729), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Nov 17 08:59:28] Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Nov 17 08:59:28] DEBUG[19064]: chan_agent.c:927 agent_bridgedchannel: Asked for bridged channel on 'SIP/sip5842_fastech-3268'/'Agent/5842', returning 'IAX2/tweety-3' [Nov 17 08:59:28] DEBUG[19064]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to write format slin [Nov 17 08:59:28] -- Started music on hold, class 'default', on channel 'IAX2/tweety-3' [Nov 17 08:59:28] DEBUG[19064]: channel.c:1711 ast_settimeout: Scheduling timer at 160 sample intervals [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:10408 handle_request_invite: Got a SIP re-invite for call 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 [Nov 17 08:59:28] We're at 64.94.196.22 port 14570 [Nov 17 08:59:28] Adding codec 0x4 (ulaw) to SDP [Nov 17 08:59:28] Adding non-codec 0x1 (telephone-event) to SDP [Nov 17 08:59:28] Reliably Transmitting (NAT) to 64.94.197.130:13644: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bK236c55ba8D9D5CA5;received=64.94.197.130 From: ;tag=7D74B61B-98F74618 To: "UST" ;tag=as653a71a7 Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 CSeq: 1 INVITE User-Agent: CoreDialPBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 216 v=0 o=root 19046 19047 IN IP4 64.94.196.22 s=session c=IN IP4 64.94.196.22 t=0 0 m=audio 14570 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:1286 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #5 [Nov 17 08:59:28] DEBUG[19072]: channel.c:1973 ast_read: Generator got voice, switching to phase locked mode [Nov 17 08:59:28] DEBUG[19072]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals [Nov 17 08:59:28] <-- SIP read from 64.94.197.130:13644: ACK sip:4847844300@64.94.196.22 SIP/2.0 Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bK531ac24c9C4F0DF From: ;tag=7D74B61B-98F74618 To: "UST" ;tag=as653a71a7 CSeq: 1 ACK Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Max-Forwards: 70 Content-Length: 0 [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: ACK sip:4847844300@64.94.196.22 SIP/2.0 (39) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bK531ac24c9C4F0DF (58) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: ;tag=7D74B61B-98F74618 (61) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: "UST" ;tag=as653a71a7 (54) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 1 ACK (11) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (54) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Max-Forwards: 70 (16) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: Content-Length: 0 (17) [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 11: (0) [Nov 17 08:59:28] --- (11 headers 0 lines)[Nov 17 08:59:28] --- [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Their Tag 7D74B61B-98F74618 Our tag: as653a71a7 [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:10980 handle_request: **** Received ACK (6) - Command in SIP ACK [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:1383 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5 [Nov 17 08:59:28] DEBUG[19064]: chan_sip.c:1394 __sip_ack: Stopping retransmission on '629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22' of Response 1: Match Found [Nov 17 08:59:30] <-- SIP read from 64.94.197.130:13644: INVITE sip:5865@fudd.coredial.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bK275ad44e1C2CF549 From: "5842" ;tag=50F303F4-75EB14AD To: CSeq: 1 INVITE Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 247 v=0 o=- 1163771773 1163771773 IN IP4 172.16.3.50 s=Polycom IP Phone c=IN IP4 172.16.3.50 t=0 0 a=sendrecv m=audio 2242 RTP/AVP 18 0 8 101 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: INVITE sip:5865@fudd.coredial.com:5060;user=phone SIP/2.0 (57) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bK275ad44e1C2CF549 (59) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "5842" ;tag=50F303F4-75EB14AD (74) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: (43) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 1 INVITE (14) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 (46) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Supported: 100rel,replaces (26) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 11: Max-Forwards: 70 (16) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 12: Content-Type: application/sdp (29) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 13: Content-Length: 247 (19) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 14: (0) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: v=0 (3) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: o=- 1163771773 1163771773 IN IP4 172.16.3.50 (44) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: s=Polycom IP Phone (18) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: c=IN IP4 172.16.3.50 (20) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: t=0 0 (5) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=sendrecv (10) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: m=audio 2242 RTP/AVP 18 0 8 101 (31) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Nov 17 08:59:30] --- (14 headers 11 lines)[Nov 17 08:59:30] --- [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3169 find_call: = No match Their Call ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Their Tag 7D74B61B-98F74618 Our tag: as653a71a7 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3121 sip_alloc: Allocating new SIP dialog for 4191040-ff0056a2-5a735863@172.16.3.50 - INVITE (With RTP) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:10980 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:997 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:1009 parse_sip_options: Found SIP option: -100rel- [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:1015 parse_sip_options: Matched SIP option: 100rel [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:1009 parse_sip_options: Found SIP option: -replaces- [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:1015 parse_sip_options: Matched SIP option: replaces [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:1026 parse_sip_options: * SIP extension value: 3 for call 4191040-ff0056a2-5a735863@172.16.3.50 [Nov 17 08:59:30] Using INVITE request as basis request - 4191040-ff0056a2-5a735863@172.16.3.50 [Nov 17 08:59:30] Sending to 172.16.3.50 : 5060 (non-NAT) [Nov 17 08:59:30] DEBUG[19064]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19064]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = 'sip5842_fastech' [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:7042 check_user_full: Setting NAT on RTP to 524288 [Nov 17 08:59:30] Reliably Transmitting (NAT) to 64.94.197.130:13644: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bK275ad44e1C2CF549;received=64.94.197.130 From: "5842" ;tag=50F303F4-75EB14AD To: ;tag=as11ac5ea5 Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 CSeq: 1 INVITE User-Agent: CoreDialPBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Proxy-Authenticate: Digest realm="pt.coredial.com", nonce="291b3ed9" Content-Length: 0 --- [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:1286 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #6 [Nov 17 08:59:30] Scheduling destruction of call '4191040-ff0056a2-5a735863@172.16.3.50' in 15000 ms [Nov 17 08:59:30] Found user 'sip5842_fastech' [Nov 17 08:59:30] <-- SIP read from 64.94.197.130:13644: ACK sip:5865@fudd.coredial.com:5060 SIP/2.0 Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bK275ad44e1C2CF549 From: "5842" ;tag=50F303F4-75EB14AD To: ;tag=as11ac5ea5 CSeq: 1 ACK Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Max-Forwards: 70 Content-Length: 0 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: ACK sip:5865@fudd.coredial.com:5060 SIP/2.0 (43) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bK275ad44e1C2CF549 (59) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "5842" ;tag=50F303F4-75EB14AD (74) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=as11ac5ea5 (58) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 1 ACK (11) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 (46) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Max-Forwards: 70 (16) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: Content-Length: 0 (17) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 11: (0) [Nov 17 08:59:30] --- (11 headers 0 lines)[Nov 17 08:59:30] --- [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 4191040-ff0056a2-5a735863@172.16.3.50 Their Tag 50F303F4-75EB14AD Our tag: as11ac5ea5 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:10980 handle_request: **** Received ACK (6) - Command in SIP ACK [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:1383 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #6 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:1394 __sip_ack: Stopping retransmission on '4191040-ff0056a2-5a735863@172.16.3.50' of Response 1: Match Found [Nov 17 08:59:30] <-- SIP read from 64.94.197.130:16164: [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: (0) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: (0) [Nov 17 08:59:30] --- (0 headers 1 lines)[Nov 17 08:59:30] --- [Nov 17 08:59:30] <-- SIP read from 64.94.197.130:13644: INVITE sip:5865@fudd.coredial.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKdb4fd0a77C5B10B6 From: "5842" ;tag=50F303F4-75EB14AD To: CSeq: 2 INVITE Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="sip5842_fastech", realm="pt.coredial.com", nonce="291b3ed9", uri="sip:5865@fudd.coredial.com:5060;user=phone", response="84c2b51275359329e1d572e94914a044", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 247 v=0 o=- 1163771773 1163771773 IN IP4 172.16.3.50 s=Polycom IP Phone c=IN IP4 172.16.3.50 t=0 0 a=sendrecv m=audio 2242 RTP/AVP 18 0 8 101 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: INVITE sip:5865@fudd.coredial.com:5060;user=phone SIP/2.0 (57) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKdb4fd0a77C5B10B6 (59) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "5842" ;tag=50F303F4-75EB14AD (74) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: (43) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 2 INVITE (14) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 (46) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Supported: 100rel,replaces (26) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 11: Proxy-Authorization: Digest username="sip5842_fastech", realm="pt.coredial.com", nonce="291b3ed9", uri="sip:5865@fudd.coredial.com:5060;user=phone", response="84c2b51275359329e1d572e94914a044", algorithm=MD5 (207) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 12: Max-Forwards: 70 (16) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 13: Content-Type: application/sdp (29) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 14: Content-Length: 247 (19) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 15: (0) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: v=0 (3) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: o=- 1163771773 1163771773 IN IP4 172.16.3.50 (44) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: s=Polycom IP Phone (18) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: c=IN IP4 172.16.3.50 (20) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: t=0 0 (5) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=sendrecv (10) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: m=audio 2242 RTP/AVP 18 0 8 101 (31) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Nov 17 08:59:30] --- (15 headers 11 lines)[Nov 17 08:59:30] --- [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 4191040-ff0056a2-5a735863@172.16.3.50 Their Tag 50F303F4-75EB14AD Our tag: as11ac5ea5 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:10980 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Nov 17 08:59:30] Using INVITE request as basis request - 4191040-ff0056a2-5a735863@172.16.3.50 [Nov 17 08:59:30] Sending to 172.16.3.50 : 5060 (NAT) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:7042 check_user_full: Setting NAT on RTP to 524288 [Nov 17 08:59:30] Found user 'sip5842_fastech' [Nov 17 08:59:30] Found RTP audio format 18 [Nov 17 08:59:30] Found RTP audio format 0 [Nov 17 08:59:30] Found RTP audio format 8 [Nov 17 08:59:30] Found RTP audio format 101 [Nov 17 08:59:30] Peer audio RTP is at port 172.16.3.50:2242 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3521 process_sdp: Peer audio RTP is at port 172.16.3.50:2242 [Nov 17 08:59:30] Found description format G729 [Nov 17 08:59:30] Found description format PCMU [Nov 17 08:59:30] Found description format PCMA [Nov 17 08:59:30] Found description format telephone-event [Nov 17 08:59:30] Capabilities: us - 0x10c (ulaw|alaw|g729), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x10c (ulaw|alaw|g729) [Nov 17 08:59:30] Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:10354 handle_request_invite: Checking SIP call limits for device sip5842_fastech [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:2202 update_call_counter: Updating call counter for incoming call [Nov 17 08:59:30] Looking for 5865 in fastech (domain fudd.coredial.com) [Nov 17 08:59:30] DEBUG[19064]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19064]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5865' AND context = 'fastech' AND priority = '1' [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:6047 build_route: build_route: Contact hop: [Nov 17 08:59:30] list_route: hop: [Nov 17 08:59:30] Transmitting (NAT) to 64.94.197.130:13644: SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKdb4fd0a77C5B10B6;received=64.94.197.130 From: "5842" ;tag=50F303F4-75EB14AD To: Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 CSeq: 2 INVITE User-Agent: CoreDialPBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- [Nov 17 08:59:30] DEBUG[19051]: chan_sip.c:11502 sip_devicestate: Checking device state for peer sip5842_fastech [Nov 17 08:59:30] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for SIP/sip5842_fastech - state 2 (In use) [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19085]: app_queue.c:471 changethread: Device 'SIP/sip5842_fastech' changed to state '2' (In use) [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5865' AND context = 'fastech' AND priority = '1' [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5865' AND context = 'fastech' AND priority = '1' [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5865' AND context = 'fastech' AND priority = '1' [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5865' AND context = 'fastech' AND priority = '1' [Nov 17 08:59:30] -- Executing GoTo("SIP/sip5842_fastech-3143", "fastech_extensions|5865|1") [Nov 17 08:59:30] -- Goto (fastech_extensions,5865,1) [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5865' AND context = 'fastech_extensions' AND priority = '1' [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5865' AND context = 'fastech_extensions' AND priority = '1' [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5865' AND context = 'fastech_extensions' AND priority = '1' [Nov 17 08:59:30] -- Executing Dial("SIP/sip5842_fastech-3143", "SIP/sip5865_fastech|20|t") [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3121 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = 'sip5865_fastech' [Nov 17 08:59:30] -- SIP Seeding peer from astdb: 'sip5865_fastech' at sip5865_fastech@64.94.197.130:16164 for 3600 [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:1867 create_addr_from_peer: Setting NAT on RTP to 524288 [Nov 17 08:59:30] DEBUG[19084]: channel.c:2813 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Nov 17 08:59:30] DEBUG[19084]: channel.c:2813 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Nov 17 08:59:30] DEBUG[19084]: channel.c:2813 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Nov 17 08:59:30] DEBUG[19084]: channel.c:2813 ast_channel_inherit_variables: Not copying variable SIPURI. [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3121 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:2061 sip_call: Outgoing Call for sip5865_fastech [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:2202 update_call_counter: Updating call counter for outgoing call [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: NOTIFY sip:sip5865_fastech@172.16.3.60 SIP/2.0 (46) [Nov 17 08:59:30] We're at 64.94.196.22 port 12790 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK1307b2ee;rport (63) [Nov 17 08:59:30] Adding codec 0x4 (ulaw) to SDP [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "NOCALLERID" ;tag=as7dddc6d4 (63) [Nov 17 08:59:30] Adding codec 0x8 (alaw) to SDP [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: (37) [Nov 17 08:59:30] Adding non-codec 0x1 (telephone-event) to SDP [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: Contact: (38) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 27b1d58f2a3e4ba43d437cae7eed08ab@64.94.196.22 (54) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: CoreDialPBX (23) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Max-Forwards: 70 (16) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Event: message-summary (22) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 11: Content-Length: 92 (18) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 12: (0) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: Messages-Waiting: no (20) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: Message-Account: sip:asterisk@64.94.196.22 (42) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 0: INVITE sip:sip5865_fastech@172.16.3.60 SIP/2.0 (46) [Nov 17 08:59:30] 12 headers, 3 lines [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK3230f530;rport (63) [Nov 17 08:59:30] Reliably Transmitting (NAT) to 64.94.197.130:16164: NOTIFY sip:sip5865_fastech@172.16.3.60 SIP/2.0 Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK1307b2ee;rport From: "NOCALLERID" ;tag=as7dddc6d4 To: Contact: Call-ID: 27b1d58f2a3e4ba43d437cae7eed08ab@64.94.196.22 CSeq: 102 NOTIFY User-Agent: CoreDialPBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 92 Messages-Waiting: no Message-Account: sip:asterisk@64.94.196.22 Voice-Message: 0/0 (0/0) --- [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 2: From: "Sean Finnegan" ;tag=as3bab6373 (60) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 3: To: (37) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 4: Contact: (32) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 (54) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 6: CSeq: 102 INVITE (16) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 7: User-Agent: CoreDialPBX (23) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 8: Max-Forwards: 70 (16) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 9: Date: Fri, 17 Nov 2006 13:59:30 GMT (35) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 11: Content-Type: application/sdp (29) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 12: Content-Length: 240 (19) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3337 parse_request: Header 13: (0) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3369 parse_request: Line: v=0 (3) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3369 parse_request: Line: o=root 19046 19046 IN IP4 64.94.196.22 (38) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3369 parse_request: Line: s=session (9) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3369 parse_request: Line: c=IN IP4 64.94.196.22 (21) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3369 parse_request: Line: t=0 0 (5) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3369 parse_request: Line: m=audio 12790 RTP/AVP 0 8 101 (29) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3369 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3369 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3369 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3369 parse_request: Line: a=fmtp:101 0-16 (15) [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:3369 parse_request: Line: a=silenceSupp:off - - - - (25) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:1286 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #9 [Nov 17 08:59:30] 13 headers, 11 lines [Nov 17 08:59:30] Reliably Transmitting (NAT) to 64.94.197.130:16164: INVITE sip:sip5865_fastech@172.16.3.60 SIP/2.0 Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK3230f530;rport From: "Sean Finnegan" ;tag=as3bab6373 To: Contact: Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 CSeq: 102 INVITE User-Agent: CoreDialPBX Max-Forwards: 70 Date: Fri, 17 Nov 2006 13:59:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 240 v=0 o=root 19046 19046 IN IP4 64.94.196.22 s=session c=IN IP4 64.94.196.22 t=0 0 m=audio 12790 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- [Nov 17 08:59:30] Scheduling destruction of call '27b1d58f2a3e4ba43d437cae7eed08ab@64.94.196.22' in 15000 ms [Nov 17 08:59:30] DEBUG[19084]: chan_sip.c:1286 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #10 [Nov 17 08:59:30] -- Called sip5865_fastech [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '5865' AND context = 'fastech_extensions' AND priority = '-1' [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:30] DEBUG[19084]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'fastech_extensions' AND priority = '-1' ORDER BY exten [Nov 17 08:59:30] DEBUG[19084]: channel.c:2348 set_format: Set channel SIP/sip5865_fastech-2b3c to read format slin [Nov 17 08:59:30] DEBUG[19084]: channel.c:2348 set_format: Set channel SIP/sip5842_fastech-3143 to write format slin [Nov 17 08:59:30] DEBUG[19084]: channel.c:2348 set_format: Set channel SIP/sip5842_fastech-3143 to read format slin [Nov 17 08:59:30] DEBUG[19084]: channel.c:2348 set_format: Set channel SIP/sip5865_fastech-2b3c to write format slin [Nov 17 08:59:30] <-- SIP read from 64.94.197.130:16164: SIP/2.0 200 OK Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK1307b2ee;rport From: "NOCALLERID" ;tag=as7dddc6d4 To: ;tag=B8A3A464-B70D74B1 CSeq: 102 NOTIFY Call-ID: 27b1d58f2a3e4ba43d437cae7eed08ab@64.94.196.22 Contact: Event: message-summary User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 Content-Length: 0 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 200 OK (14) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK1307b2ee;rport (63) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "NOCALLERID" ;tag=as7dddc6d4 (63) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=B8A3A464-B70D74B1 (59) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 102 NOTIFY (16) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 27b1d58f2a3e4ba43d437cae7eed08ab@64.94.196.22 (54) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: Event: message-summary (22) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 (54) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Content-Length: 0 (17) [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: (0) [Nov 17 08:59:30] --- (10 headers 0 lines)[Nov 17 08:59:30] --- [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 27b1d58f2a3e4ba43d437cae7eed08ab@64.94.196.22 Their Tag Our tag: as7dddc6d4 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:1383 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #9 [Nov 17 08:59:30] DEBUG[19064]: chan_sip.c:1394 __sip_ack: Stopping retransmission on '27b1d58f2a3e4ba43d437cae7eed08ab@64.94.196.22' of Request 102: Match Found [Nov 17 08:59:30] Destroying call '27b1d58f2a3e4ba43d437cae7eed08ab@64.94.196.22' [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:1177 retrans_pkt: SIP TIMER: Rescheduling retransmission #10 (1) INVITE - 5 [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:1191 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #10)) [Nov 17 08:59:31] Retransmitting #1 (NAT) to 64.94.197.130:16164: INVITE sip:sip5865_fastech@172.16.3.60 SIP/2.0 Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK3230f530;rport From: "Sean Finnegan" ;tag=as3bab6373 To: Contact: Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 CSeq: 102 INVITE User-Agent: CoreDialPBX Max-Forwards: 70 Date: Fri, 17 Nov 2006 13:59:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 240 v=0 o=root 19046 19046 IN IP4 64.94.196.22 s=session c=IN IP4 64.94.196.22 t=0 0 m=audio 12790 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- [Nov 17 08:59:31] <-- SIP read from 64.94.197.130:16164: SIP/2.0 100 Trying Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK3230f530;rport From: "Sean Finnegan" ;tag=as3bab6373 To: ;tag=5B2A0565-86F1282E CSeq: 102 INVITE Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Contact: User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 Content-Length: 0 [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 100 Trying (18) [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK3230f530;rport (63) [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "Sean Finnegan" ;tag=as3bab6373 (60) [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=5B2A0565-86F1282E (59) [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 102 INVITE (16) [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 (54) [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 (54) [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Content-Length: 0 (17) [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: (0) [Nov 17 08:59:31] --- (9 headers 0 lines)[Nov 17 08:59:31] --- [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Their Tag Our tag: as3bab6373 [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:1438 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #10 - INVITE (got response) [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:1447 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0c7acdfe23e90dfc788399252d0efb13@64.94.196.22' Request 102: Found [Nov 17 08:59:31] DEBUG[19064]: chan_sip.c:9459 handle_response_invite: SIP response 100 to standard invite [Nov 17 08:59:32] <-- SIP read from 64.94.197.130:16164: SIP/2.0 100 Trying Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK3230f530;rport From: "Sean Finnegan" ;tag=as3bab6373 To: ;tag=5B2A0565-86F1282E CSeq: 102 INVITE Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Contact: User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 Content-Length: 0 [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 100 Trying (18) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK3230f530;rport (63) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "Sean Finnegan" ;tag=as3bab6373 (60) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=5B2A0565-86F1282E (59) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 102 INVITE (16) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 (54) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 (54) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Content-Length: 0 (17) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: (0) [Nov 17 08:59:32] --- (9 headers 0 lines)[Nov 17 08:59:32] --- [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Their Tag 5B2A0565-86F1282E Our tag: as3bab6373 [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:1447 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0c7acdfe23e90dfc788399252d0efb13@64.94.196.22' Request 102: Found [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:9459 handle_response_invite: SIP response 100 to standard invite [Nov 17 08:59:32] <-- SIP read from 64.94.197.130:16164: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK3230f530;rport From: "Sean Finnegan" ;tag=as3bab6373 To: ;tag=5B2A0565-86F1282E CSeq: 102 INVITE Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Contact: User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 Allow-Events: talk,hold,conference Content-Length: 0 [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK3230f530;rport (63) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "Sean Finnegan" ;tag=as3bab6373 (60) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=5B2A0565-86F1282E (59) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 102 INVITE (16) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 (54) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 (54) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Allow-Events: talk,hold,conference (34) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Content-Length: 0 (17) [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: (0) [Nov 17 08:59:32] --- (10 headers 0 lines)[Nov 17 08:59:32] --- [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Their Tag 5B2A0565-86F1282E Our tag: as3bab6373 [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:1447 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0c7acdfe23e90dfc788399252d0efb13@64.94.196.22' Request 102: Found [Nov 17 08:59:32] DEBUG[19064]: chan_sip.c:9459 handle_response_invite: SIP response 180 to standard invite [Nov 17 08:59:32] -- SIP/sip5865_fastech-2b3c is ringing [Nov 17 08:59:32] DEBUG[19051]: chan_sip.c:11502 sip_devicestate: Checking device state for peer sip5865_fastech [Nov 17 08:59:32] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for SIP/sip5865_fastech - state 6 (Ringing) [Nov 17 08:59:32] Transmitting (NAT) to 64.94.197.130:13644: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKdb4fd0a77C5B10B6;received=64.94.197.130 From: "5842" ;tag=50F303F4-75EB14AD To: ;tag=as0c4e11f2 Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 CSeq: 2 INVITE User-Agent: CoreDialPBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- [Nov 17 08:59:32] DEBUG[19086]: app_queue.c:471 changethread: Device 'SIP/sip5865_fastech' changed to state '6' (Ringing) [Nov 17 08:59:33] <-- SIP read from 64.94.197.130:16164: SIP/2.0 200 OK Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK3230f530;rport From: "Sean Finnegan" ;tag=as3bab6373 To: ;tag=5B2A0565-86F1282E CSeq: 102 INVITE Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 Content-Type: application/sdp Content-Length: 185 v=0 o=- 1163771275 1163771275 IN IP4 172.16.3.60 s=Polycom IP Phone c=IN IP4 172.16.3.60 t=0 0 m=audio 2222 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 200 OK (14) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK3230f530;rport (63) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "Sean Finnegan" ;tag=as3bab6373 (60) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=5B2A0565-86F1282E (59) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 102 INVITE (16) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 (54) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 (54) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Content-Type: application/sdp (29) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: Content-Length: 185 (19) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 11: (0) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: v=0 (3) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: o=- 1163771275 1163771275 IN IP4 172.16.3.60 (44) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: s=Polycom IP Phone (18) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: c=IN IP4 172.16.3.60 (20) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: t=0 0 (5) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: m=audio 2222 RTP/AVP 0 101 (26) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3369 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Nov 17 08:59:33] --- (11 headers 8 lines)[Nov 17 08:59:33] --- [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Their Tag 5B2A0565-86F1282E Our tag: as3bab6373 [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:1372 __sip_ack: Acked pending invite 102 [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:1394 __sip_ack: Stopping retransmission on '0c7acdfe23e90dfc788399252d0efb13@64.94.196.22' of Request 102: Match Found [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:9459 handle_response_invite: SIP response 200 to standard invite [Nov 17 08:59:33] Found RTP audio format 0 [Nov 17 08:59:33] Found RTP audio format 101 [Nov 17 08:59:33] Peer audio RTP is at port 172.16.3.60:2222 [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3521 process_sdp: Peer audio RTP is at port 172.16.3.60:2222 [Nov 17 08:59:33] Found description format PCMU [Nov 17 08:59:33] Found description format telephone-event [Nov 17 08:59:33] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Nov 17 08:59:33] Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:6047 build_route: build_route: Contact hop: [Nov 17 08:59:33] list_route: hop: [Nov 17 08:59:33] set_destination: Parsing for address/port to send to [Nov 17 08:59:33] set_destination: set destination to 172.16.3.60, port 5060 [Nov 17 08:59:33] Transmitting (NAT) to 64.94.197.130:16164: ACK sip:sip5865_fastech@172.16.3.60 SIP/2.0 Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK126d7c77;rport From: "Sean Finnegan" ;tag=as3bab6373 To: ;tag=5B2A0565-86F1282E Contact: Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 CSeq: 102 ACK User-Agent: CoreDialPBX Max-Forwards: 70 Content-Length: 0 --- [Nov 17 08:59:33] -- SIP/sip5865_fastech-2b3c answered SIP/sip5842_fastech-3143 [Nov 17 08:59:33] DEBUG[19051]: chan_sip.c:11502 sip_devicestate: Checking device state for peer sip5865_fastech [Nov 17 08:59:33] DEBUG[19084]: channel.c:2348 set_format: Set channel SIP/sip5842_fastech-3143 to read format slin [Nov 17 08:59:33] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for SIP/sip5865_fastech - state 2 (In use) [Nov 17 08:59:33] DEBUG[19084]: channel.c:2348 set_format: Set channel SIP/sip5865_fastech-2b3c to write format slin [Nov 17 08:59:33] DEBUG[19087]: app_queue.c:471 changethread: Device 'SIP/sip5865_fastech' changed to state '2' (In use) [Nov 17 08:59:33] DEBUG[19084]: channel.c:2348 set_format: Set channel SIP/sip5865_fastech-2b3c to read format slin [Nov 17 08:59:33] DEBUG[19084]: channel.c:2348 set_format: Set channel SIP/sip5842_fastech-3143 to write format slin [Nov 17 08:59:33] DEBUG[19084]: chan_sip.c:2527 sip_answer: sip_answer(SIP/sip5842_fastech-3143) [Nov 17 08:59:33] DEBUG[19051]: chan_sip.c:11502 sip_devicestate: Checking device state for peer sip5842_fastech [Nov 17 08:59:33] We're at 64.94.196.22 port 16864 [Nov 17 08:59:33] Adding codec 0x100 (g729) to SDP [Nov 17 08:59:33] DEBUG[19051]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/sip5842_fastech-3143' [Nov 17 08:59:33] Adding codec 0x4 (ulaw) to SDP [Nov 17 08:59:33] Adding codec 0x8 (alaw) to SDP [Nov 17 08:59:33] Adding non-codec 0x1 (telephone-event) to SDP [Nov 17 08:59:33] Reliably Transmitting (NAT) to 64.94.197.130:13644: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKdb4fd0a77C5B10B6;received=64.94.197.130 From: "5842" ;tag=50F303F4-75EB14AD To: ;tag=as0c4e11f2 Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 CSeq: 2 INVITE User-Agent: CoreDialPBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 287 v=0 o=root 19046 19046 IN IP4 64.94.196.22 s=session c=IN IP4 64.94.196.22 t=0 0 m=audio 16864 RTP/AVP 18 0 8 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- [Nov 17 08:59:33] DEBUG[19084]: chan_sip.c:1286 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #12 [Nov 17 08:59:33] -- Attempting native bridge of SIP/sip5842_fastech-3143 and SIP/sip5865_fastech-2b3c [Nov 17 08:59:33] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for SIP/sip5842_fastech - state 2 (In use) [Nov 17 08:59:33] DEBUG[19088]: app_queue.c:471 changethread: Device 'SIP/sip5842_fastech' changed to state '2' (In use) [Nov 17 08:59:33] <-- SIP read from 64.94.197.130:13644: ACK sip:5865@64.94.196.22 SIP/2.0 Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKd89af68aC592B7B5 From: "5842" ;tag=50F303F4-75EB14AD To: ;tag=as0c4e11f2 CSeq: 2 ACK Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Proxy-Authorization: Digest username="sip5842_fastech", realm="pt.coredial.com", nonce="291b3ed9", uri="sip:5865@fudd.coredial.com:5060;user=phone", response="84c2b51275359329e1d572e94914a044", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: ACK sip:5865@64.94.196.22 SIP/2.0 (33) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKd89af68aC592B7B5 (59) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "5842" ;tag=50F303F4-75EB14AD (74) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=as0c4e11f2 (58) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 2 ACK (11) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 (46) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Proxy-Authorization: Digest username="sip5842_fastech", realm="pt.coredial.com", nonce="291b3ed9", uri="sip:5865@fudd.coredial.com:5060;user=phone", response="84c2b51275359329e1d572e94914a044", algorithm=MD5 (207) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: Max-Forwards: 70 (16) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 11: Content-Length: 0 (17) [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 12: (0) [Nov 17 08:59:33] --- (12 headers 0 lines)[Nov 17 08:59:33] --- [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3169 find_call: = No match Their Call ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Their Tag 5B2A0565-86F1282E Our tag: as3bab6373 [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 4191040-ff0056a2-5a735863@172.16.3.50 Their Tag 50F303F4-75EB14AD Our tag: as0c4e11f2 [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:10980 handle_request: **** Received ACK (6) - Command in SIP ACK [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:1383 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #12 [Nov 17 08:59:33] DEBUG[19064]: chan_sip.c:1394 __sip_ack: Stopping retransmission on '4191040-ff0056a2-5a735863@172.16.3.50' of Response 2: Match Found [Nov 17 08:59:33] DEBUG[19084]: rtp.c:477 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 64.94.197.130:16350 [Nov 17 08:59:33] DEBUG[19084]: rtp.c:1341 ast_rtp_write: Ooh, format changed from unknown to g729 [Nov 17 08:59:33] DEBUG[19084]: rtp.c:477 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 64.94.197.130:13850 [Nov 17 08:59:33] DEBUG[19084]: rtp.c:1341 ast_rtp_write: Ooh, format changed from unknown to ulaw [Nov 17 08:59:34] DEBUG[19084]: rtp.c:406 ast_rtcp_read: RTCP NAT: Got RTCP from other end. Now sending to address 64.94.197.130:16351 [Nov 17 08:59:34] DEBUG[19084]: rtp.c:410 ast_rtcp_read: Got RTCP report of 88 bytes [Nov 17 08:59:35] <-- SIP read from 64.94.197.130:13644: REFER sip:4847844300@64.94.196.22 SIP/2.0 Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKa5fec9c1C4436F From: ;tag=7D74B61B-98F74618 To: "UST" ;tag=as653a71a7 CSeq: 2 REFER Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Refer-To: Referred-By: Max-Forwards: 70 Content-Length: 0 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: REFER sip:4847844300@64.94.196.22 SIP/2.0 (41) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKa5fec9c1C4436F (57) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: ;tag=7D74B61B-98F74618 (61) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: "UST" ;tag=as653a71a7 (54) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 2 REFER (13) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (54) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Refer-To: (151) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Referred-By: (52) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: Max-Forwards: 70 (16) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 11: Content-Length: 0 (17) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 12: (0) [Nov 17 08:59:35] --- (12 headers 0 lines)[Nov 17 08:59:35] --- [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3169 find_call: = No match Their Call ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Their Tag 5B2A0565-86F1282E Our tag: as3bab6373 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3169 find_call: = No match Their Call ID: 4191040-ff0056a2-5a735863@172.16.3.50 Their Tag 50F303F4-75EB14AD Our tag: as0c4e11f2 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Their Tag 7D74B61B-98F74618 Our tag: as653a71a7 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:10980 handle_request: **** Received REFER (9) - Command in SIP REFER [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:10520 handle_request_refer: SIP call transfer received for call 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (REFER)! [Nov 17 08:59:35] Transfer to 5865 in fastech [Nov 17 08:59:35] Transfer from sip5842_fastech in fastech [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:6744 get_refer_info: Assigning Replace-Call-ID Info 4191040-ff0056a2-5a735863@172.16.3.50 to REPLACE_CALL_ID [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:10532 handle_request_refer: 202 Accepted (supervised) [Nov 17 08:59:35] DEBUG[19064]: chan_agent.c:927 agent_bridgedchannel: Asked for bridged channel on 'SIP/sip5842_fastech-3268'/'Agent/5842', returning 'IAX2/tweety-3' [Nov 17 08:59:35] DEBUG[19064]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to write format ulaw [Nov 17 08:59:35] -- Stopped music on hold on IAX2/tweety-3 [Nov 17 08:59:35] DEBUG[19064]: channel.c:1711 ast_settimeout: Scheduling timer at 0 sample intervals [Nov 17 08:59:35] DEBUG[19064]: channel.c:2747 ast_channel_masquerade: Planning to masquerade channel IAX2/tweety-3 into the structure of SIP/sip5842_fastech-3143 [Nov 17 08:59:35] DEBUG[19064]: channel.c:2760 ast_channel_masquerade: Done planning to masquerade channel IAX2/tweety-3 into the structure of SIP/sip5842_fastech-3143 [Nov 17 08:59:35] Transmitting (NAT) to 64.94.197.130:13644: SIP/2.0 202 Accepted Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKa5fec9c1C4436F;received=64.94.197.130 From: ;tag=7D74B61B-98F74618 To: "UST" ;tag=as653a71a7 Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 CSeq: 2 REFER User-Agent: CoreDialPBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- [Nov 17 08:59:35] DEBUG[19084]: channel.c:2870 ast_do_masquerade: Actually Masquerading IAX2/tweety-3(6) into the structure of SIP/sip5842_fastech-3143(6) [Nov 17 08:59:35] DEBUG[19084]: channel.c:2881 ast_do_masquerade: Got clone lock for masquerade on 'IAX2/tweety-3' at 0x85dcb84 [Nov 17 08:59:35] DEBUG[19084]: chan_sip.c:2411 sip_hangup: Hangup call IAX2/tweety-3, SIP callid 4191040-ff0056a2-5a735863@172.16.3.50) [Nov 17 08:59:35] DEBUG[19084]: chan_sip.c:2419 sip_hangup: update_call_counter(sip5842_fastech) - decrement call limit counter [Nov 17 08:59:35] DEBUG[19084]: chan_sip.c:2202 update_call_counter: Updating call counter for incoming call [Nov 17 08:59:35] set_destination: Parsing for address/port to send to [Nov 17 08:59:35] set_destination: Parsing for address/port to send to [Nov 17 08:59:35] set_destination: set destination to 172.16.3.50, port 5060 [Nov 17 08:59:35] set_destination: set destination to 172.16.3.50, port 5060 [Nov 17 08:59:35] Reliably Transmitting (NAT) to 64.94.197.130:13644: BYE sip:sip5842_fastech@172.16.3.50 SIP/2.0 Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK5e4b155d;rport From: ;tag=as0c4e11f2 To: "5842" ;tag=50F303F4-75EB14AD Contact: Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 CSeq: 102 BYE User-Agent: CoreDialPBX Max-Forwards: 70 Content-Length: 0 --- [Nov 17 08:59:35] Reliably Transmitting (NAT) to 64.94.197.130:13644: NOTIFY sip:sip5842_fastech@172.16.3.50 SIP/2.0 Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK1670cc52;rport From: "UST" ;tag=as653a71a7 To: ;tag=7D74B61B-98F74618 Contact: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 CSeq: 103 NOTIFY User-Agent: CoreDialPBX Max-Forwards: 70 Event: refer;id=2 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Content-Length: 14 SIP/2.0 200 OK --- [Nov 17 08:59:35] DEBUG[19084]: chan_sip.c:1286 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #13 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:1286 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #14 [Nov 17 08:59:35] DEBUG[19084]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to write format slin [Nov 17 08:59:35] set_destination: Parsing for address/port to send to [Nov 17 08:59:35] DEBUG[19084]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to read format slin [Nov 17 08:59:35] set_destination: set destination to 172.16.3.50, port 5060 [Nov 17 08:59:35] DEBUG[19084]: channel.c:3042 ast_do_masquerade: Putting channel IAX2/tweety-3 in 64/64 formats [Nov 17 08:59:35] Reliably Transmitting (NAT) to 64.94.197.130:13644: BYE sip:sip5842_fastech@172.16.3.50 SIP/2.0 Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK07355c6d;rport From: "UST" ;tag=as653a71a7 To: ;tag=7D74B61B-98F74618 Contact: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 CSeq: 104 BYE User-Agent: CoreDialPBX Max-Forwards: 70 Content-Length: 0 --- [Nov 17 08:59:35] DEBUG[19084]: channel.c:3077 ast_do_masquerade: Released clone lock on 'SIP/sip5842_fastech-3143' [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:1286 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #15 [Nov 17 08:59:35] DEBUG[19084]: channel.c:3086 ast_do_masquerade: Done Masquerading IAX2/tweety-3 (6) [Nov 17 08:59:35] DEBUG[19072]: channel.c:3265 ast_generic_bridge: Didn't get a frame from channel: SIP/sip5842_fastech-3143 [Nov 17 08:59:35] DEBUG[19084]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to read format ulaw [Nov 17 08:59:35] DEBUG[19084]: channel.c:2348 set_format: Set channel SIP/sip5865_fastech-2b3c to write format ulaw [Nov 17 08:59:35] DEBUG[19084]: channel.c:2348 set_format: Set channel SIP/sip5865_fastech-2b3c to read format ulaw [Nov 17 08:59:35] DEBUG[19084]: channel.c:2348 set_format: Set channel IAX2/tweety-3 to write format ulaw [Nov 17 08:59:35] DEBUG[19072]: channel.c:3540 ast_channel_bridge: Bridge stops bridging channels SIP/sip5842_fastech-3143 and Agent/5842 [Nov 17 08:59:35] DEBUG[19072]: channel.c:1323 ast_hangup: Hanging up channel 'Agent/5842' [Nov 17 08:59:35] DEBUG[19072]: chan_agent.c:760 agent_hangup: Hangup called for state Up [Nov 17 08:59:35] DEBUG[19072]: channel.c:1323 ast_hangup: Hanging up channel 'SIP/sip5842_fastech-3268' [Nov 17 08:59:35] DEBUG[19072]: chan_sip.c:2411 sip_hangup: Hangup call SIP/sip5842_fastech-3268, SIP callid 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22) [Nov 17 08:59:35] DEBUG[19072]: chan_sip.c:2419 sip_hangup: update_call_counter(sip5842_fastech) - decrement call limit counter [Nov 17 08:59:35] DEBUG[19072]: chan_sip.c:2202 update_call_counter: Updating call counter for incoming call [Nov 17 08:59:35] DEBUG[19072]: chan_agent.c:782 agent_hangup: Hungup, howlong is 0, autologoff is 15 [Nov 17 08:59:35] DEBUG[19051]: chan_sip.c:11502 sip_devicestate: Checking device state for peer sip5842_fastech [Nov 17 08:59:35] DEBUG[19072]: pbx.c:2313 __ast_pbx_run: Spawn extension (fastech_custom_QUEUE_UST,s,3) exited non-zero on 'SIP/sip5842_fastech-3143' [Nov 17 08:59:35] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for SIP/sip5842_fastech - state 2 (In use) [Nov 17 08:59:35] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for Agent/5842 - state 1 (Not in use) [Nov 17 08:59:35] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for Agent/5842 - state 1 (Not in use) [Nov 17 08:59:35] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:35] DEBUG[19090]: app_queue.c:471 changethread: Device 'Agent/5842' changed to state '1' (Not in use) [Nov 17 08:59:35] DEBUG[19089]: app_queue.c:471 changethread: Device 'SIP/sip5842_fastech' changed to state '2' (In use) [Nov 17 08:59:35] DEBUG[19091]: app_queue.c:471 changethread: Device 'Agent/5842' changed to state '1' (Not in use) [Nov 17 08:59:35] DEBUG[19072]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'h' AND context = 'fastech_custom_QUEUE_UST' AND priority = '1' [Nov 17 08:59:35] DEBUG[19072]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:35] DEBUG[19072]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'fastech_custom_QUEUE_UST' AND priority = '1' ORDER BY exten [Nov 17 08:59:35] DEBUG[19072]: channel.c:1328 ast_hangup: Hanging up zombie 'SIP/sip5842_fastech-3143' [Nov 17 08:59:35] DEBUG[19051]: chan_sip.c:11502 sip_devicestate: Checking device state for peer sip5842_fastech [Nov 17 08:59:35] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for SIP/sip5842_fastech - state 1 (Not in use) [Nov 17 08:59:35] DEBUG[19092]: app_queue.c:471 changethread: Device 'SIP/sip5842_fastech' changed to state '1' (Not in use) [Nov 17 08:59:35] <-- SIP read from 64.94.197.130:13644: SIP/2.0 200 OK Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK5e4b155d;rport From: ;tag=as0c4e11f2 To: "5842" ;tag=50F303F4-75EB14AD CSeq: 102 BYE Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Content-Length: 0 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 200 OK (14) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK5e4b155d;rport (63) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: ;tag=as0c4e11f2 (60) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: "5842" ;tag=50F303F4-75EB14AD (72) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 102 BYE (13) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 4191040-ff0056a2-5a735863@172.16.3.50 (46) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Content-Length: 0 (17) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: (0) [Nov 17 08:59:35] --- (9 headers 0 lines)[Nov 17 08:59:35] --- [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3169 find_call: = No match Their Call ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Their Tag 5B2A0565-86F1282E Our tag: as3bab6373 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 4191040-ff0056a2-5a735863@172.16.3.50 Their Tag 50F303F4-75EB14AD Our tag: as0c4e11f2 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:1383 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #13 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:1394 __sip_ack: Stopping retransmission on '4191040-ff0056a2-5a735863@172.16.3.50' of Request 102: Match Found [Nov 17 08:59:35] Destroying call '4191040-ff0056a2-5a735863@172.16.3.50' [Nov 17 08:59:35] <-- SIP read from 64.94.197.130:13644: SIP/2.0 200 OK Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK1670cc52;rport From: "UST" ;tag=as653a71a7 To: ;tag=7D74B61B-98F74618 CSeq: 103 NOTIFY Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Contact: Event: refer;id=2 User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Content-Length: 0 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 200 OK (14) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK1670cc52;rport (63) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "UST" ;tag=as653a71a7 (56) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=7D74B61B-98F74618 (59) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 103 NOTIFY (16) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (54) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: Event: refer;id=2 (17) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Content-Length: 0 (17) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: (0) [Nov 17 08:59:35] --- (10 headers 0 lines)[Nov 17 08:59:35] --- [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3169 find_call: = No match Their Call ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Their Tag 5B2A0565-86F1282E Our tag: as3bab6373 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Their Tag 7D74B61B-98F74618 Our tag: as653a71a7 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:1383 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #14 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:1394 __sip_ack: Stopping retransmission on '629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22' of Request 103: Match Found [Nov 17 08:59:35] <-- SIP read from 64.94.197.130:13644: BYE sip:4847844300@64.94.196.22 SIP/2.0 Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKc6f5bc1eA5D00359 From: ;tag=7D74B61B-98F74618 To: "UST" ;tag=as653a71a7 CSeq: 3 BYE Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Max-Forwards: 70 Content-Length: 0 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: BYE sip:4847844300@64.94.196.22 SIP/2.0 (39) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKc6f5bc1eA5D00359 (59) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: ;tag=7D74B61B-98F74618 (61) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: "UST" ;tag=as653a71a7 (54) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 3 BYE (11) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (54) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Max-Forwards: 70 (16) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Content-Length: 0 (17) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: (0) [Nov 17 08:59:35] --- (10 headers 0 lines)[Nov 17 08:59:35] --- [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3169 find_call: = No match Their Call ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Their Tag 5B2A0565-86F1282E Our tag: as3bab6373 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Their Tag 7D74B61B-98F74618 Our tag: as653a71a7 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:10980 handle_request: **** Received BYE (8) - Command in SIP BYE [Nov 17 08:59:35] Sending to 172.16.3.50 : 5060 (NAT) [Nov 17 08:59:35] Transmitting (NAT) to 64.94.197.130:13644: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.16.3.50;branch=z9hG4bKc6f5bc1eA5D00359;received=64.94.197.130 From: ;tag=7D74B61B-98F74618 To: "UST" ;tag=as653a71a7 Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 CSeq: 3 BYE User-Agent: CoreDialPBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- [Nov 17 08:59:35] <-- SIP read from 64.94.197.130:13644: SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK07355c6d;rport From: "UST" ;tag=as653a71a7 To: ;tag=7D74B61B-98F74618 CSeq: 104 BYE Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 Content-Length: 0 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: SIP/2.0 500 Internal Server Error (33) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 64.94.196.22:5060;branch=z9hG4bK07355c6d;rport (63) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: "UST" ;tag=as653a71a7 (56) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: ;tag=7D74B61B-98F74618 (59) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 104 BYE (13) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 (54) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.0.2.0076 (54) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Content-Length: 0 (17) [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: (0) [Nov 17 08:59:35] --- (9 headers 0 lines)[Nov 17 08:59:35] --- [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3169 find_call: = No match Their Call ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Their Tag 5B2A0565-86F1282E Our tag: as3bab6373 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22 Their Tag 7D74B61B-98F74618 Our tag: as653a71a7 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:1383 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15 [Nov 17 08:59:35] DEBUG[19064]: chan_sip.c:1394 __sip_ack: Stopping retransmission on '629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22' of Request 104: Match Found [Nov 17 08:59:35] -- Incoming call: Got SIP response 500 "Internal Server Error" back from 172.16.3.50 [Nov 17 08:59:35] Destroying call '629ccf9b0f82cf0c693b2f827d3c7c86@64.94.196.22' [Nov 17 08:59:38] <-- SIP read from 64.94.197.130:16164: BYE sip:5842@64.94.196.22 SIP/2.0 Via: SIP/2.0/UDP 172.16.3.60;branch=z9hG4bK7811b228C896E667 From: ;tag=5B2A0565-86F1282E To: "Sean Finnegan" ;tag=as3bab6373 CSeq: 1 BYE Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Contact: User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 Max-Forwards: 70 Content-Length: 0 [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 0: BYE sip:5842@64.94.196.22 SIP/2.0 (33) [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 1: Via: SIP/2.0/UDP 172.16.3.60;branch=z9hG4bK7811b228C896E667 (59) [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 2: From: ;tag=5B2A0565-86F1282E (61) [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 3: To: "Sean Finnegan" ;tag=as3bab6373 (58) [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 4: CSeq: 1 BYE (11) [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 5: Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 (54) [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 6: Contact: (42) [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_301-UA/2.0.2.0076 (54) [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 8: Max-Forwards: 70 (16) [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 9: Content-Length: 0 (17) [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3337 parse_request: Header 10: (0) [Nov 17 08:59:38] --- (10 headers 0 lines)[Nov 17 08:59:38] --- [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:3169 find_call: = Found Their Call ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 Their Tag 5B2A0565-86F1282E Our tag: as3bab6373 [Nov 17 08:59:38] DEBUG[19064]: chan_sip.c:10980 handle_request: **** Received BYE (8) - Command in SIP BYE [Nov 17 08:59:38] Sending to 172.16.3.60 : 5060 (NAT) [Nov 17 08:59:38] Transmitting (NAT) to 64.94.197.130:16164: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.16.3.60;branch=z9hG4bK7811b228C896E667;received=64.94.197.130 From: ;tag=5B2A0565-86F1282E To: "Sean Finnegan" ;tag=as3bab6373 Call-ID: 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22 CSeq: 1 BYE User-Agent: CoreDialPBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing --- [Nov 17 08:59:38] DEBUG[19084]: channel.c:3265 ast_generic_bridge: Didn't get a frame from channel: SIP/sip5865_fastech-2b3c [Nov 17 08:59:38] DEBUG[19084]: channel.c:3540 ast_channel_bridge: Bridge stops bridging channels IAX2/tweety-3 and SIP/sip5865_fastech-2b3c [Nov 17 08:59:38] DEBUG[19084]: channel.c:1323 ast_hangup: Hanging up channel 'SIP/sip5865_fastech-2b3c' [Nov 17 08:59:38] DEBUG[19084]: chan_sip.c:2411 sip_hangup: Hangup call SIP/sip5865_fastech-2b3c, SIP callid 0c7acdfe23e90dfc788399252d0efb13@64.94.196.22) [Nov 17 08:59:38] DEBUG[19084]: chan_sip.c:2419 sip_hangup: update_call_counter(sip5865_fastech) - decrement call limit counter [Nov 17 08:59:38] DEBUG[19084]: chan_sip.c:2202 update_call_counter: Updating call counter for outgoing call [Nov 17 08:59:38] DEBUG[19084]: app_dial.c:1605 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Nov 17 08:59:38] DEBUG[19051]: chan_sip.c:11502 sip_devicestate: Checking device state for peer sip5865_fastech [Nov 17 08:59:38] DEBUG[19084]: pbx.c:2313 __ast_pbx_run: Spawn extension (fastech_extensions,5865,1) exited non-zero on 'IAX2/tweety-3' [Nov 17 08:59:38] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for SIP/sip5865_fastech - state 1 (Not in use) [Nov 17 08:59:38] DEBUG[19093]: app_queue.c:471 changethread: Device 'SIP/sip5865_fastech' changed to state '1' (Not in use) [Nov 17 08:59:38] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:38] DEBUG[19084]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'h' AND context = 'fastech_extensions' AND priority = '1' [Nov 17 08:59:38] DEBUG[19084]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Nov 17 08:59:38] DEBUG[19084]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND context = 'fastech_extensions' AND priority = '1' ORDER BY exten [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '"UST" <4847844300>' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '4847844300' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '5865' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'fastech_extensions' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'SIP/sip5842_fastech-3143' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'SIP/sip5865_fastech-2b3c' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'Dial' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'SIP/sip5865_fastech|20|t' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '2006-11-17 08:59:30' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '2006-11-17 08:59:33' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '2006-11-17 08:59:38' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '8' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '5' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'fastech' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '1163771970.5' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '(null)' [Nov 17 08:59:38] DEBUG[19084]: cdr_addon_mysql.c:207 mysql_log: cdr_mysql: inserting a CDR record. [Nov 17 08:59:38] DEBUG[19084]: cdr_addon_mysql.c:223 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2006-11-17 08:59:30','\"UST\" <4847844300>','4847844300','5865','fastech_extensions', 'SIP/sip5842_fastech-3143','SIP/sip5865_fastech-2b3c','Dial','SIP/sip5865_fastech|20|t',8,5,'ANSWERED',3,'fastech','1163771970.5','') [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '"UST" <4847844300>' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '4847844300' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '5865' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'fastech_extensions' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'IAX2/tweety-3' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'Agent/5842' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'Queue' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'fastech_UST|TtwW||' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '2006-11-17 08:59:21' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '2006-11-17 08:59:21' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '2006-11-17 08:59:38' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '17' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '17' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is 'fastech' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '1163771961.0' [Nov 17 08:59:38] DEBUG[19084]: pbx.c:1519 pbx_substitute_variables_helper_full: Function result is '(null)' [Nov 17 08:59:38] DEBUG[19084]: cdr_addon_mysql.c:207 mysql_log: cdr_mysql: inserting a CDR record. [Nov 17 08:59:38] DEBUG[19084]: cdr_addon_mysql.c:223 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2006-11-17 08:59:21','\"UST\" <4847844300>','4847844300','5865','fastech_extensions', 'IAX2/tweety-3','Agent/5842','Queue','fastech_UST|TtwW||',17,17,'ANSWERED',3,'fastech','1163771961.0','') [Nov 17 08:59:38] DEBUG[19084]: channel.c:1323 ast_hangup: Hanging up channel 'IAX2/tweety-3' [Nov 17 08:59:38] DEBUG[19084]: chan_iax2.c:3068 iax2_hangup: We're hanging up IAX2/tweety-3 now... [Nov 17 08:59:38] -- Hungup 'IAX2/tweety-3' [Nov 17 08:59:38] DEBUG[19051]: chan_iax2.c:9327 iax2_devicestate: Checking device state for device tweety [Nov 17 08:59:38] DEBUG[19051]: chan_iax2.c:9335 iax2_devicestate: iax2_devicestate(tweety): Found peer. What's device state of tweety? addr=415522368, defaddr=0 maxms=2000, lastms=1 [Nov 17 08:59:38] DEBUG[19051]: devicestate.c:187 do_state_change: Changing state for IAX2/tweety - state 1 (Not in use) [Nov 17 08:59:38] DEBUG[19094]: app_queue.c:471 changethread: Device 'IAX2/tweety' changed to state '1' (Not in use) [Nov 17 08:59:39] Destroying call '0c7acdfe23e90dfc788399252d0efb13@64.94.196.22' stop now [Nov 17 08:59:43] Beginning asterisk shutdown.... [Nov 17 08:59:43] Executing last minute cleanups [Nov 17 08:59:43] == Destroying musiconhold processes [Nov 17 08:59:43] DEBUG[19046]: res_musiconhold.c:1077 ast_moh_destroy: killing 19057! [Nov 17 08:59:43] DEBUG[19046]: res_musiconhold.c:1085 ast_moh_destroy: mpg123 pid 19057 and child died after 90274 bytes read [Nov 17 08:59:43] DEBUG[19046]: res_musiconhold.c:1077 ast_moh_destroy: killing 19055! [Nov 17 08:59:43] DEBUG[19046]: res_musiconhold.c:1085 ast_moh_destroy: mpg123 pid 19055 and child died after 2524170 bytes read [Nov 17 08:59:43] DEBUG[19046]: res_musiconhold.c:1077 ast_moh_destroy: killing 19056! [Nov 17 08:59:43] DEBUG[19046]: res_musiconhold.c:1085 ast_moh_destroy: mpg123 pid 19056 and child died after 6750218 bytes read [Nov 17 08:59:43] Asterisk cleanly ending (0).