Sep 20 12:18:55 DEBUG[27963] chan_sip.c: Allocating new SIP dialog for 0009b7da-07e9000c-21327d87-0cd48974@1.2.3.4 - INVITE (With RTP) Sep 20 12:18:55 DEBUG[27963] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE Sep 20 12:18:55 DEBUG[27963] chan_sip.c: * SIP extension value: 17 for call 0009b7da-07e9000c-21327d87-0cd48974@1.2.3.4 Sep 20 12:18:55 DEBUG[27963] chan_sip.c: Setting NAT on RTP to 0 Sep 20 12:18:55 DEBUG[27963] chan_sip.c: Setting NAT on VRTP to 0 Sep 20 12:18:55 DEBUG[27963] chan_sip.c: = Found Their Call ID: 0009b7da-07e9000c-21327d87-0cd48974@1.2.3.4 Their Tag 0009b7da07e989083ccb374c-6491436a Our tag: as30ed2709 Sep 20 12:18:55 DEBUG[27963] chan_sip.c: **** Received ACK (6) - Command in SIP ACK Sep 20 12:18:55 DEBUG[27963] chan_sip.c: Stopping retransmission on '0009b7da-07e9000c-21327d87-0cd48974@1.2.3.4' of Response 101: Match Found Sep 20 12:18:55 DEBUG[27963] chan_sip.c: = Found Their Call ID: 0009b7da-07e9000c-21327d87-0cd48974@1.2.3.4 Their Tag 0009b7da07e989083ccb374c-6491436a Our tag: as30ed2709 Sep 20 12:18:55 DEBUG[27963] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE Sep 20 12:18:55 DEBUG[27963] chan_sip.c: Setting NAT on RTP to 0 Sep 20 12:18:55 DEBUG[27963] chan_sip.c: Setting NAT on VRTP to 0 Sep 20 12:18:55 DEBUG[27963] chan_sip.c: Checking SIP call limits for device X88381 Sep 20 12:18:55 DEBUG[27963] chan_sip.c: Updating call counter for incoming call Sep 20 12:18:55 DEBUG[27963] chan_sip.c: build_route: Contact hop: Sep 20 12:18:55 DEBUG[28022] pbx.c: Launching 'Dial' Sep 20 12:18:55 DEBUG[28022] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Sep 20 12:18:55 DEBUG[28022] chan_sip.c: Setting NAT on RTP to 0 Sep 20 12:18:55 DEBUG[28022] chan_sip.c: Setting NAT on VRTP to 0 Sep 20 12:18:55 DEBUG[27954] chan_sip.c: Checking device state for peer X88381 Sep 20 12:18:55 DEBUG[27954] devicestate.c: Changing state for SIP/X88381 - state 2 (In use) Sep 20 12:18:55 DEBUG[28023] app_queue.c: Device 'SIP/X88381' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 20 12:18:55 DEBUG[28022] channel.c: Not copying variable STACK-SuperUsers-87762-1. Sep 20 12:18:55 DEBUG[28022] channel.c: Not copying variable SIPCALLID. Sep 20 12:18:55 DEBUG[28022] channel.c: Not copying variable SIPUSERAGENT. Sep 20 12:18:55 DEBUG[28022] channel.c: Not copying variable SIPDOMAIN. Sep 20 12:18:55 DEBUG[28022] channel.c: Not copying variable SIPURI. Sep 20 12:18:55 DEBUG[28022] chan_sip.c: Outgoing Call for 87762 Sep 20 12:18:55 DEBUG[28022] chan_sip.c: Updating call counter for outgoing call Sep 20 12:18:55 DEBUG[28022] channel.c: Set channel SIP/ccm-gw-08b4d8f0 to read format ulaw Sep 20 12:18:55 DEBUG[28022] channel.c: Set channel SIP/X88381-bf242b50 to write format ulaw Sep 20 12:18:55 DEBUG[28022] channel.c: Set channel SIP/X88381-bf242b50 to read format ulaw Sep 20 12:18:55 DEBUG[28022] channel.c: Set channel SIP/ccm-gw-08b4d8f0 to write format ulaw Sep 20 12:18:55 DEBUG[27963] chan_sip.c: = Found Their Call ID: 6aa66aa8163318f053ef9ea700e15593@AsteriskServer Their Tag Our tag: as4cb6012c Sep 20 12:18:55 DEBUG[27963] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6aa66aa8163318f053ef9ea700e15593@AsteriskServer' Request 102: Found Sep 20 12:18:55 DEBUG[27963] chan_sip.c: SIP response 100 to standard invite Sep 20 12:18:55 DEBUG[27963] chan_sip.c: = Found Their Call ID: 6aa66aa8163318f053ef9ea700e15593@AsteriskServer Their Tag 16958040 Our tag: as4cb6012c Sep 20 12:18:55 DEBUG[27963] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6aa66aa8163318f053ef9ea700e15593@AsteriskServer' Request 102: Found Sep 20 12:18:55 DEBUG[27963] chan_sip.c: SIP response 180 to standard invite Sep 20 12:18:55 DEBUG[27954] chan_sip.c: Checking device state for peer ccm-gw Sep 20 12:18:55 DEBUG[27954] devicestate.c: Changing state for SIP/ccm-gw - state 6 (Ringing) Sep 20 12:18:55 DEBUG[28024] app_queue.c: Device 'SIP/ccm-gw' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. Sep 20 12:18:55 DEBUG[27963] chan_sip.c: = Found Their Call ID: 6aa66aa8163318f053ef9ea700e15593@AsteriskServer Their Tag 16958040 Our tag: as4cb6012c Sep 20 12:18:55 DEBUG[27963] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6aa66aa8163318f053ef9ea700e15593@AsteriskServer' Request 102: Found Sep 20 12:18:55 DEBUG[27963] chan_sip.c: SIP response 183 to standard invite Sep 20 12:18:55 DEBUG[28022] rtp.c: Ooh, format changed from unknown to ulaw Sep 20 12:18:56 DEBUG[28022] rtp.c: Ooh, format changed from unknown to ulaw Sep 20 12:18:58 DEBUG[27963] chan_sip.c: = Found Their Call ID: 6aa66aa8163318f053ef9ea700e15593@AsteriskServer Their Tag 16958040 Our tag: as4cb6012c Sep 20 12:18:58 DEBUG[27963] chan_sip.c: Acked pending invite 102 Sep 20 12:18:58 DEBUG[27963] chan_sip.c: Stopping retransmission on '6aa66aa8163318f053ef9ea700e15593@AsteriskServer' of Request 102: Match Found Sep 20 12:18:58 DEBUG[27963] chan_sip.c: SIP response 200 to standard invite Sep 20 12:18:58 DEBUG[27963] chan_sip.c: build_route: Contact hop: Sep 20 12:18:58 DEBUG[27954] chan_sip.c: Checking device state for peer ccm-gw Sep 20 12:18:58 DEBUG[27954] devicestate.c: Changing state for SIP/ccm-gw - state 2 (In use) Sep 20 12:18:58 DEBUG[28022] channel.c: Set channel SIP/X88381-bf242b50 to read format ulaw Sep 20 12:18:58 DEBUG[28022] channel.c: Set channel SIP/ccm-gw-08b4d8f0 to write format ulaw Sep 20 12:18:58 DEBUG[28022] channel.c: Set channel SIP/ccm-gw-08b4d8f0 to read format ulaw Sep 20 12:18:58 DEBUG[28022] channel.c: Set channel SIP/X88381-bf242b50 to write format ulaw Sep 20 12:18:58 DEBUG[28022] chan_sip.c: sip_answer(SIP/X88381-bf242b50) Sep 20 12:18:58 DEBUG[27954] chan_sip.c: Checking device state for peer X88381 Sep 20 12:18:58 DEBUG[27954] channel.c: Avoiding initial deadlock for 'SIP/X88381-bf242b50' Sep 20 12:18:58 DEBUG[28025] app_queue.c: Device 'SIP/ccm-gw' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 20 12:18:58 DEBUG[27954] devicestate.c: Changing state for SIP/X88381 - state 2 (In use) Sep 20 12:18:58 DEBUG[28026] app_queue.c: Device 'SIP/X88381' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 20 12:18:58 DEBUG[27963] chan_sip.c: = No match Their Call ID: 6aa66aa8163318f053ef9ea700e15593@AsteriskServer Their Tag 16958040 Our tag: as4cb6012c Sep 20 12:18:58 DEBUG[27963] chan_sip.c: = Found Their Call ID: 0009b7da-07e9000c-21327d87-0cd48974@1.2.3.4 Their Tag 0009b7da07e989083ccb374c-6491436a Our tag: as30d892e4 Sep 20 12:18:58 DEBUG[27963] chan_sip.c: **** Received ACK (6) - Command in SIP ACK Sep 20 12:18:58 DEBUG[27963] chan_sip.c: Stopping retransmission on '0009b7da-07e9000c-21327d87-0cd48974@1.2.3.4' of Response 102: Match Found Sep 20 12:19:03 DEBUG[28022] rtp.c: Sending dtmf: 35 (#), at 1.2.3.4 Sep 20 12:19:03 DEBUG[28022] channel.c: Got DTMF on channel (SIP/X88381-bf242b50) Sep 20 12:19:03 DEBUG[28022] channel.c: Bridge stops bridging channels SIP/X88381-bf242b50 and SIP/ccm-gw-08b4d8f0 Sep 20 12:19:03 DEBUG[28022] res_features.c: Feature interpret: chan=SIP/X88381-bf242b50, peer=SIP/ccm-gw-08b4d8f0, sense=1, features=18 Sep 20 12:19:03 DEBUG[28022] res_features.c: Set time limit to 500 Sep 20 12:19:05 DEBUG[28022] rtp.c: Sending dtmf: 35 (#), at 1.2.3.4 Sep 20 12:19:05 DEBUG[28022] channel.c: Got DTMF on channel (SIP/X88381-bf242b50) Sep 20 12:19:05 DEBUG[28022] channel.c: Bridge stops bridging channels SIP/X88381-bf242b50 and SIP/ccm-gw-08b4d8f0 Sep 20 12:19:05 DEBUG[28022] res_features.c: Timed out for feature! Sep 20 12:19:05 DEBUG[28022] channel.c: Set channel SIP/ccm-gw-08b4d8f0 to write format slin Sep 20 12:19:05 DEBUG[28022] channel.c: Scheduling timer at 160 sample intervals Sep 20 12:19:05 DEBUG[28022] channel.c: Generator got voice, switching to phase locked mode Sep 20 12:19:05 DEBUG[28022] channel.c: Scheduling timer at 0 sample intervals Sep 20 12:19:05 DEBUG[28022] channel.c: Auto-deactivating generator Sep 20 12:19:05 DEBUG[28022] channel.c: Set channel SIP/ccm-gw-08b4d8f0 to write format ulaw Sep 20 12:19:05 DEBUG[28022] channel.c: Scheduling timer at 0 sample intervals Sep 20 12:19:07 DEBUG[28022] rtp.c: Sending dtmf: 35 (#), at 1.2.3.4 Sep 20 12:19:07 DEBUG[28022] channel.c: Got DTMF on channel (SIP/X88381-bf242b50) Sep 20 12:19:07 DEBUG[28022] channel.c: Bridge stops bridging channels SIP/X88381-bf242b50 and SIP/ccm-gw-08b4d8f0 Sep 20 12:19:07 DEBUG[28022] res_features.c: Feature interpret: chan=SIP/X88381-bf242b50, peer=SIP/ccm-gw-08b4d8f0, sense=1, features=18 Sep 20 12:19:07 DEBUG[28022] res_features.c: Set time limit to 500 Sep 20 12:19:07 DEBUG[28022] rtp.c: Sending dtmf: 35 (#), at 1.2.3.4 Sep 20 12:19:07 DEBUG[28022] channel.c: Got DTMF on channel (SIP/X88381-bf242b50) Sep 20 12:19:07 DEBUG[28022] channel.c: Bridge stops bridging channels SIP/X88381-bf242b50 and SIP/ccm-gw-08b4d8f0 Sep 20 12:19:07 DEBUG[28022] res_features.c: Timed out for feature! Sep 20 12:19:07 DEBUG[28022] channel.c: Set channel SIP/ccm-gw-08b4d8f0 to write format slin Sep 20 12:19:07 DEBUG[28022] channel.c: Scheduling timer at 160 sample intervals Sep 20 12:19:07 DEBUG[28022] channel.c: Generator got voice, switching to phase locked mode Sep 20 12:19:07 DEBUG[28022] channel.c: Scheduling timer at 0 sample intervals Sep 20 12:19:08 DEBUG[28022] channel.c: Auto-deactivating generator Sep 20 12:19:08 DEBUG[28022] channel.c: Set channel SIP/ccm-gw-08b4d8f0 to write format ulaw Sep 20 12:19:08 DEBUG[28022] channel.c: Scheduling timer at 0 sample intervals Sep 20 12:19:10 DEBUG[27963] chan_sip.c: = No match Their Call ID: 6aa66aa8163318f053ef9ea700e15593@AsteriskServer Their Tag 16958040 Our tag: as4cb6012c Sep 20 12:19:10 DEBUG[27963] chan_sip.c: = Found Their Call ID: 0009b7da-07e9000c-21327d87-0cd48974@1.2.3.4 Their Tag 0009b7da07e989083ccb374c-6491436a Our tag: as30d892e4 Sep 20 12:19:10 DEBUG[27963] chan_sip.c: **** Received BYE (8) - Command in SIP BYE Sep 20 12:19:10 DEBUG[28022] channel.c: Didn't get a frame from channel: SIP/X88381-bf242b50 Sep 20 12:19:10 DEBUG[28022] channel.c: Bridge stops bridging channels SIP/X88381-bf242b50 and SIP/ccm-gw-08b4d8f0 Sep 20 12:19:10 DEBUG[28022] channel.c: Hanging up channel 'SIP/ccm-gw-08b4d8f0' Sep 20 12:19:10 DEBUG[28022] chan_sip.c: Hangup call SIP/ccm-gw-08b4d8f0, SIP callid 6aa66aa8163318f053ef9ea700e15593@AsteriskServer) Sep 20 12:19:10 DEBUG[28022] chan_sip.c: update_call_counter(87762) - decrement call limit counter Sep 20 12:19:10 DEBUG[28022] chan_sip.c: Updating call counter for outgoing call Sep 20 12:19:10 DEBUG[28022] app_dial.c: Exiting with DIALSTATUS=ANSWER. Sep 20 12:19:10 DEBUG[28022] pbx.c: Spawn extension (SuperUsers,87762,1) exited non-zero on 'SIP/X88381-bf242b50' Sep 20 12:19:10 DEBUG[27954] chan_sip.c: Checking device state for peer ccm-gw Sep 20 12:19:10 DEBUG[27954] devicestate.c: Changing state for SIP/ccm-gw - state 1 (Not in use) Sep 20 12:19:10 DEBUG[28027] app_queue.c: Device 'SIP/ccm-gw' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Sep 20 12:19:10 DEBUG[28022] channel.c: Hanging up channel 'SIP/X88381-bf242b50' Sep 20 12:19:10 DEBUG[28022] chan_sip.c: Hangup call SIP/X88381-bf242b50, SIP callid 0009b7da-07e9000c-21327d87-0cd48974@1.2.3.4) Sep 20 12:19:10 DEBUG[28022] chan_sip.c: update_call_counter(X88381) - decrement call limit counter Sep 20 12:19:10 DEBUG[28022] chan_sip.c: Updating call counter for incoming call Sep 20 12:19:10 DEBUG[27954] chan_sip.c: Checking device state for peer X88381 Sep 20 12:19:10 DEBUG[27954] devicestate.c: Changing state for SIP/X88381 - state 1 (Not in use) Sep 20 12:19:10 DEBUG[28028] app_queue.c: Device 'SIP/X88381' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Sep 20 12:19:10 DEBUG[27963] chan_sip.c: = Found Their Call ID: 6aa66aa8163318f053ef9ea700e15593@AsteriskServer Their Tag 16958040 Our tag: as4cb6012c Sep 20 12:19:10 DEBUG[27963] chan_sip.c: Stopping retransmission on '6aa66aa8163318f053ef9ea700e15593@AsteriskServer' of Request 103: Match Found