[Feb  7 16:21:11] DEBUG[22761]: pbx.c:1693 pbx_extension_helper: Launching 'Dial'
    -- Executing [s@macro-dial:13] Dial("SIP/5050-08602df8", "SIP/5050|45|TtKk") in new stack
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:15474 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:4414 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:2751 create_addr_from_peer: Our T38 capability (3856)
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:2705 do_setnat: Setting NAT on RTP to Off
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:2715 do_setnat: Setting NAT on UDPTL to Off
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:3917 sip_new: *** Our native formats are 0x100 (g729) 
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:3918 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:3919 sip_new: *** Our capabilities are 0x8010c (ulaw|alaw|g729|h263) 
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:3920 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) 
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:3922 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:3943 sip_new: This channel will not be able to handle video.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-13.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-12.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable ARG2.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable ARG1.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-9.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-6.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable status.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-5.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-2.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable status .
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-monitor-s-1.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-11.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-10.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-3.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-2.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-1.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable ARG7.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable ARG6.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable ARG5.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable ARG4.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable ARG3.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-12.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-9.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-5.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-2.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-macro-dialinexten-s-1.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable STACK-extensions-5050-1.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Feb  7 16:21:11] DEBUG[22761]: channel.c:3205 ast_channel_inherit_variables: Not copying variable SIPURI.
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:2956 sip_call: Outgoing Call for 5050
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:3137 update_call_counter: Updating call counter for outgoing call
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:2974 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:6294 add_sdp: ** Our capability: 0x8010c (ulaw|alaw|g729|h263) Video flag: False
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:6295 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:6312 add_sdp: This call needs video offers, but there's no video support enabled!
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:6420 add_sdp: -- Done with adding codecs to SDP
[Feb  7 16:21:11] DEBUG[22761]: channel.c:2291 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:6464 add_sdp: Done building SDP. Settling with this capability: 0x8010c (ulaw|alaw|g729|h263)
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:1681 initialize_initreq: Initializing initreq for method INVITE - callid 7a3bbb2b7afab7a63d164e9c7b3dd16f@172.16.0.167
    -- Called 5050
[Feb  7 16:21:11] DEBUG[22761]: channel.c:2755 set_format: Set channel SIP/5050-08614350 to read format slin
[Feb  7 16:21:11] DEBUG[22761]: channel.c:2755 set_format: Set channel SIP/5050-08602df8 to write format slin
[Feb  7 16:21:11] DEBUG[22761]: channel.c:2755 set_format: Set channel SIP/5050-08602df8 to read format slin
[Feb  7 16:21:11] DEBUG[22761]: channel.c:2755 set_format: Set channel SIP/5050-08614350 to write format slin
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:4478 find_call: = Found Their Call ID: 7a3bbb2b7afab7a63d164e9c7b3dd16f@172.16.0.167 Their Tag  Our tag: as56ae52bc
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:2184 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7a3bbb2b7afab7a63d164e9c7b3dd16f@172.16.0.167' Request 102: Found
[Feb  7 16:21:11] DEBUG[22761]: chan_sip.c:11808 handle_response_invite: SIP response 100 to standard invite
[Feb  7 16:21:12] DEBUG[22761]: chan_sip.c:4478 find_call: = Found Their Call ID: 7a3bbb2b7afab7a63d164e9c7b3dd16f@172.16.0.167 Their Tag 26417483631789147215 Our tag: as56ae52bc[Feb  7 16:21:12] DEBUG[22761]: chan_sip.c:2184 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7a3bbb2b7afab7a63d164e9c7b3dd16f@172.16.0.167' Request 102: Found
[Feb  7 16:21:12] DEBUG[22761]: chan_sip.c:11808 handle_response_invite: SIP response 180 to standard invite
[Feb  7 16:21:12] DEBUG[22761]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-08614350
    -- SIP/5050-08614350 is ringing
[Feb  7 16:21:12] DEBUG[22761]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 5050
[Feb  7 16:21:12] DEBUG[22761]: chan_sip.c:15405 sip_devicestate: Checking device state for peer 5050
[Feb  7 16:21:12] DEBUG[22761]: devicestate.c:366 do_state_change: Changing state for SIP/5050 - state 1 (Not in use)
[Feb  7 16:21:12] DEBUG[22761]: app_queue.c:568 changethread: Device 'SIP/5050' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:4196 sip_rtp_read: Oooh, format changed to 4
[Feb  7 16:21:13] DEBUG[22761]: channel.c:2755 set_format: Set channel SIP/5050-08614350 to read format slin
[Feb  7 16:21:13] DEBUG[22761]: channel.c:2755 set_format: Set channel SIP/5050-08614350 to write format slin
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:6519 transmit_response_with_sdp: Setting framing from config on incoming call
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:6294 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:6295 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:6420 add_sdp: -- Done with adding codecs to SDP
[Feb  7 16:21:13] DEBUG[22761]: channel.c:2291 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:6464 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Feb  7 16:21:13] DEBUG[22761]: rtp.c:2757 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Feb  7 16:21:13] DEBUG[22761]: rtp.c:2774 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:4478 find_call: = Found Their Call ID: 7a3bbb2b7afab7a63d164e9c7b3dd16f@172.16.0.167 Their Tag 26417483631789147215 Our tag: as56ae52bc[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:2125 __sip_ack: Acked pending invite 102
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:2141 __sip_ack: Stopping retransmission on '7a3bbb2b7afab7a63d164e9c7b3dd16f@172.16.0.167' of Request 102: Match Found
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:11808 handle_response_invite: SIP response 200 to standard invite
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:5211 process_sdp: T38 state changed to 0 on channel SIP/5050-08614350
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:5291 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:5298 process_sdp: We have an owner, now see if we need to change this call
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:3137 update_call_counter: Updating call counter for outgoing call
--- set_address_from_contact host '172.16.0.192'
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:8034 build_route: build_route: Contact hop: <sip:5050@172.16.0.192:5060>
[Feb  7 16:21:13] DEBUG[22761]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-08614350
    -- SIP/5050-08614350 answered SIP/5050-08602df8
[Feb  7 16:21:13] DEBUG[22761]: channel.c:2755 set_format: Set channel SIP/5050-08602df8 to read format ulaw
[Feb  7 16:21:13] DEBUG[22761]: channel.c:2755 set_format: Set channel SIP/5050-08614350 to write format ulaw
[Feb  7 16:21:13] DEBUG[22761]: channel.c:2755 set_format: Set channel SIP/5050-08614350 to read format ulaw
[Feb  7 16:21:13] DEBUG[22761]: channel.c:2755 set_format: Set channel SIP/5050-08602df8 to write format ulaw
[Feb  7 16:21:13] DEBUG[22761]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-08602df8
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:3579 sip_answer: SIP answering channel: SIP/5050-08602df8
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:6519 transmit_response_with_sdp: Setting framing from config on incoming call
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:6294 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:6295 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:6420 add_sdp: -- Done with adding codecs to SDP
[Feb  7 16:21:13] DEBUG[22761]: channel.c:2291 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:6464 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Feb  7 16:21:13] DEBUG[22761]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 5050
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:15405 sip_devicestate: Checking device state for peer 5050
[Feb  7 16:21:13] DEBUG[22761]: devicestate.c:366 do_state_change: Changing state for SIP/5050 - state 1 (Not in use)
[Feb  7 16:21:13] DEBUG[22761]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 5050
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:15405 sip_devicestate: Checking device state for peer 5050
[Feb  7 16:21:13] DEBUG[22761]: devicestate.c:366 do_state_change: Changing state for SIP/5050 - state 1 (Not in use)
[Feb  7 16:21:13] DEBUG[22761]: app_queue.c:568 changethread: Device 'SIP/5050' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb  7 16:21:13] DEBUG[22761]: app_queue.c:568 changethread: Device 'SIP/5050' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:4478 find_call: = No match Their Call ID: 7a3bbb2b7afab7a63d164e9c7b3dd16f@172.16.0.167 Their Tag 26417483631789147215 Our tag: as56ae52bc
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:4478 find_call: = Found Their Call ID: E034DC7E-1DD1-11B2-A20C-AFEAB2037000@172.16.0.192 Their Tag 26417483201520065531 Our tag: as16ef2e22
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:14779 handle_request: **** Received ACK (6) - Command in SIP ACK
[Feb  7 16:21:13] DEBUG[22761]: chan_sip.c:2141 __sip_ack: Stopping retransmission on 'E034DC7E-1DD1-11B2-A20C-AFEAB2037000@172.16.0.192' of Response 2: Match Found
[Feb  7 16:21:13] DEBUG[22761]: rtp.c:2774 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Feb  7 16:21:13] DEBUG[22761]: rtp.c:2757 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Feb  7 16:21:13] DEBUG[22761]: rtp.c:2774 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:644 send_dtmf: Sending dtmf: 35 (#), at 172.16.0.192
[Feb  7 16:21:14] DTMF[22761]: channel.c:2162 __ast_read: DTMF begin '#' received on SIP/5050-08602df8
[Feb  7 16:21:14] DEBUG[22761]: channel.c:3753 ast_generic_bridge: Got DTMF begin on channel (SIP/5050-08602df8)
[Feb  7 16:21:14] DEBUG[22761]: channel.c:4035 ast_channel_bridge: Bridge stops bridging channels SIP/5050-08602df8 and SIP/5050-08614350
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:644 send_dtmf: Sending dtmf: 35 (#), at 172.16.0.192
[Feb  7 16:21:14] DTMF[22761]: channel.c:2162 __ast_read: DTMF begin '#' received on SIP/5050-08614350
[Feb  7 16:21:14] DEBUG[22761]: channel.c:3753 ast_generic_bridge: Got DTMF begin on channel (SIP/5050-08614350)
[Feb  7 16:21:14] DEBUG[22761]: channel.c:4035 ast_channel_bridge: Bridge stops bridging channels SIP/5050-08602df8 and SIP/5050-08614350
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:644 send_dtmf: Sending dtmf: 35 (#), at 172.16.0.192
[Feb  7 16:21:14] DTMF[22761]: channel.c:2135 __ast_read: DTMF end '#' received on SIP/5050-08602df8
[Feb  7 16:21:14] DEBUG[22761]: channel.c:3753 ast_generic_bridge: Got DTMF end on channel (SIP/5050-08602df8)
[Feb  7 16:21:14] DEBUG[22761]: channel.c:4035 ast_channel_bridge: Bridge stops bridging channels SIP/5050-08602df8 and SIP/5050-08614350
[Feb  7 16:21:14] DEBUG[22761]: res_features.c:1041 ast_feature_interpret: Feature interpret: chan=SIP/5050-08602df8, peer=SIP/5050-08614350, sense=1, features=34
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:644 send_dtmf: Sending dtmf: 35 (#), at 172.16.0.192
[Feb  7 16:21:14] DTMF[22761]: channel.c:2135 __ast_read: DTMF end '#' received on SIP/5050-08614350
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:14] DEBUG[22761]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 16:21:19] DEBUG[22761]: manager.c:2065 process_message: Manager received command 'Challenge'
[Feb  7 16:21:19] DEBUG[22761]: channel.c:1375 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/5050-08614350'
[Feb  7 16:21:19] DEBUG[22761]: channel.c:1375 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/5050-08602df8'
Beginning asterisk shutdown....
[Feb  7 16:21:19] DEBUG[22761]: channel.c:3707 ast_generic_bridge: Didn't get a frame from channel: SIP/5050-08614350
[Feb  7 16:21:19] DEBUG[22761]: channel.c:4035 ast_channel_bridge: Bridge stops bridging channels SIP/5050-08602df8 and SIP/5050-08614350
[Feb  7 16:21:19] DEBUG[22761]: channel.c:1589 ast_hangup: Hanging up channel 'SIP/5050-08614350'
[Feb  7 16:21:19] DEBUG[22761]: chan_sip.c:3430 sip_hangup: Hangup call SIP/5050-08614350, SIP callid 7a3bbb2b7afab7a63d164e9c7b3dd16f@172.16.0.167)
[Feb  7 16:21:19] DEBUG[22761]: chan_sip.c:3137 update_call_counter: Updating call counter for outgoing call
[Feb  7 16:21:19] DEBUG[22761]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-08614350
[Feb  7 16:21:19] DEBUG[22761]: rtp.c:1556 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Feb  7 16:21:19] DEBUG[22761]: app_dial.c:1688 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Feb  7 16:21:19] DEBUG[22761]: app_macro.c:265 _macro_exec: Spawn extension (macro-dial,s,13) exited non-zero on 'SIP/5050-08602df8' in macro 'dial'
[Feb  7 16:21:19] DEBUG[22761]: app_macro.c:265 _macro_exec: Spawn extension (macro-dial,s,13) exited non-zero on 'SIP/5050-08602df8' in macro 'dialinexten'
[Feb  7 16:21:19] DEBUG[22761]: pbx.c:2289 __ast_pbx_run: Spawn extension (macro-dial,s,13) exited non-zero on 'SIP/5050-08602df8'
  == Spawn extension (macro-dial, s, 13) exited non-zero on 'SIP/5050-08602df8'