rendered paste body[Apr 21 12:22:03] DEBUG[15610]: chan_sip.c:7312 sip_alloc: Allocating new SIP dialog for 3c27c7f8e57e-t9iceszcrded@snom360 - INVITE (No RTP)
[Apr 21 12:22:03] DEBUG[15610]: rtp_engine.c:271 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x10d3a308'
[Apr 21 12:22:03] DEBUG[15610]: res_rtp_asterisk.c:472 ast_rtp_new: Allocated port 11986 for RTP instance '0x10d3a308'
[Apr 21 12:22:03] DEBUG[15610]: rtp_engine.c:280 ast_rtp_instance_new: RTP instance '0x10d3a308' is setup and ready to go
[Apr 21 12:22:03] DEBUG[15610]: res_rtp_asterisk.c:2370 ast_rtp_prop_set: Setup RTCP on RTP instance '0x10d3a308'
== Using SIP RTP CoS mark 5
[Apr 21 12:22:03] DEBUG[15610]: chan_sip.c:4735 do_setnat: Setting NAT on RTP to Off
[Apr 21 12:22:03] DEBUG[15610]: rtp_engine.c:472 ast_rtp_codecs_payloads_set_m_type: Setting payload 4 based on m type on 0x48350b18
[Apr 21 12:22:03] DEBUG[15610]: rtp_engine.c:472 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x48350b18
[Apr 21 12:22:03] DEBUG[15610]: rtp_engine.c:593 ast_rtp_codecs_payload_formats: Incorporating payload 4 on 0x48350b18
[Apr 21 12:22:03] DEBUG[15610]: rtp_engine.c:593 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x48350b18
[Apr 21 12:22:03] DEBUG[15610]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x10d3a308'
[Apr 21 12:22:03] DEBUG[15610]: chan_sip.c:21827 handle_request_invite: Checking SIP call limits for device 200
[Apr 21 12:22:03] DEBUG[21218]: pbx.c:4178 pbx_extension_helper: Launching 'Dial'
-- Executing [4001@from-internal:1] Dial("SIP/200-00000005", "DAHDI/1,k") in new stack
[Apr 21 12:22:03] DEBUG[21218]: sig_analog.c:803 analog_available: analog_available 1
[Apr 21 12:22:03] DEBUG[21218]: chan_dahdi.c:13479 dahdi_request: Using channel 1
[Apr 21 12:22:03] DEBUG[21218]: sig_analog.c:780 analog_request: analog_request 1
[Apr 21 12:22:03] DEBUG[21218]: dsp.c:470 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Apr 21 12:22:03] DEBUG[21218]: dsp.c:470 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Apr 21 12:22:03] DEBUG[21218]: rtp_engine.c:1456 ast_rtp_instance_early_bridge_make_compatible: Can't find native functions for channel 'DAHDI/1-1'
[Apr 21 12:22:03] DEBUG[21218]: rtp_engine.c:1518 ast_rtp_instance_early_bridge_make_compatible: Seeded SDP of 'DAHDI/1-1' with that of 'SIP/200-00000005'
[Apr 21 12:22:03] DEBUG[21218]: channel.c:6107 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Apr 21 12:22:03] DEBUG[21218]: channel.c:6107 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Apr 21 12:22:03] DEBUG[21218]: channel.c:6107 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Apr 21 12:22:03] DEBUG[21218]: channel.c:6107 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Apr 21 12:22:03] DEBUG[21218]: channel.c:6107 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Apr 21 12:22:03] DEBUG[21218]: channel.c:6107 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Apr 21 12:22:03] DEBUG[21218]: channel.c:6107 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Apr 21 12:22:03] DEBUG[21218]: channel.c:6107 ast_channel_inherit_variables: Not copying variable SIPURI.
[Apr 21 12:22:03] DEBUG[21218]: sig_analog.c:1004 analog_call: CALLING CID_NAME: powermac CID_NUM:: 200
-- Called DAHDI/1
[Apr 21 12:22:03] WARNING[21218]: app_dial.c:2353 dial_exec_full: Invalid timeout specified: 'k'. Setting timeout to infinite
[Apr 21 12:22:03] DEBUG[21218]: channel.c:5112 set_format: Set channel DAHDI/1-1 to read format slin
[Apr 21 12:22:03] DEBUG[21218]: codec_dahdi.c:405 dahdi_translate: Opening transcoder channel from slin to g723.
[Apr 21 12:22:03] DEBUG[21218]: codec_dahdi.c:419 dahdi_translate: Using soft_slin support on source
[Apr 21 12:22:03] DEBUG[21218]: channel.c:5112 set_format: Set channel SIP/200-00000005 to write format slin
[Apr 21 12:22:03] DEBUG[21218]: codec_dahdi.c:405 dahdi_translate: Opening transcoder channel from g723 to slin.
[Apr 21 12:22:03] DEBUG[21218]: codec_dahdi.c:423 dahdi_translate: Using soft_slin support on destination
[Apr 21 12:22:03] DEBUG[21218]: channel.c:5112 set_format: Set channel SIP/200-00000005 to read format slin
[Apr 21 12:22:03] DEBUG[21218]: channel.c:5112 set_format: Set channel DAHDI/1-1 to write format slin
-- DAHDI/1-1 is ringing
[Apr 21 12:22:05] DEBUG[21218]: sig_analog.c:3465 analog_exception: analog_exception 1
[Apr 21 12:22:05] DEBUG[21218]: sig_analog.c:3559 analog_exception: Exception on 8, channel 1
[Apr 21 12:22:05] DEBUG[21218]: sig_analog.c:2618 __analog_handle_event: __analog_handle_event 1
[Apr 21 12:22:05] DEBUG[21218]: sig_analog.c:2645 __analog_handle_event: Got event ANALOG_EVENT_RINGEROFF(8) on channel 1 (index 0)
[Apr 21 12:22:05] DEBUG[21218]: sig_analog.c:364 analog_send_callerid: Sending callerid. CID_NAME: 'powermac' CID_NUM: '200'
-- DAHDI/1-1 is ringing
[Apr 21 12:22:06] DEBUG[15609]: chan_dahdi.c:11738 do_monitor: Monitor doohicky got event Ring/Answered on channel 3
[Apr 21 12:22:06] DEBUG[15609]: sig_analog.c:3577 analog_handle_init_event: channel (3) - signaling (2) - event (ANALOG_EVENT_RINGOFFHOOK)
[Apr 21 12:22:06] DEBUG[15609]: dsp.c:470 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Apr 21 12:22:06] DEBUG[15609]: dsp.c:470 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Apr 21 12:22:06] DEBUG[21225]: sig_analog.c:1729 __analog_ss_thread: __analog_ss_thread 3
-- Starting simple switch on 'DAHDI/3-1'
[Apr 21 12:22:07] DEBUG[21225]: sig_analog.c:1589 analog_handle_dtmf: Begin DTMF digit: 0x2A '*' on DAHDI/3-1
[Apr 21 12:22:07] DEBUG[21225]: chan_dahdi.c:2030 my_handle_dtmf: Begin DTMF digit: 0x2A '*' on DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21225]: sig_analog.c:1589 analog_handle_dtmf: End DTMF digit: 0x2A '*' on DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21225]: chan_dahdi.c:2030 my_handle_dtmf: End DTMF digit: 0x2A '*' on DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21225]: sig_analog.c:2080 __analog_ss_thread: waitfordigit returned '*' (42), timeout = 0
[Apr 21 12:22:08] DEBUG[21225]: sig_analog.c:1589 analog_handle_dtmf: Begin DTMF digit: 0x38 '8' on DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21225]: chan_dahdi.c:2030 my_handle_dtmf: Begin DTMF digit: 0x38 '8' on DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21225]: sig_analog.c:1589 analog_handle_dtmf: End DTMF digit: 0x38 '8' on DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21225]: chan_dahdi.c:2030 my_handle_dtmf: End DTMF digit: 0x38 '8' on DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21225]: sig_analog.c:2080 __analog_ss_thread: waitfordigit returned '8' (56), timeout = 0
[Apr 21 12:22:08] DEBUG[21225]: chan_dahdi.c:4856 dahdi_enable_ec: Enabled echo cancellation on channel 3
[Apr 21 12:22:08] DEBUG[21225]: features.c:5724 ast_pickup_call: Call pickup on chan 'DAHDI/1-1' by 'DAHDI/3-1'
[Apr 21 12:22:08] DEBUG[21225]: chan_dahdi.c:9285 dahdi_indicate: Requested indication 22 on channel DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21225]: chan_dahdi.c:9285 dahdi_indicate: Requested indication -1 on channel DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21225]: channel.c:5911 __ast_channel_masquerade: Planning to masquerade channel DAHDI/3-1 into the structure of DAHDI/1-1
[Apr 21 12:22:08] DEBUG[21225]: channel.c:5921 __ast_channel_masquerade: Done planning to masquerade channel DAHDI/3-1 into the structure of DAHDI/1-1
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:9285 dahdi_indicate: Requested indication -1 on channel DAHDI/1-1
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:7493 dahdi_fixup: New owner for channel 1 is DAHDI/3-1<MASQ>
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:4803 update_conf: Updated conferencing on 1, with 0 conference users
[Apr 21 12:22:08] DEBUG[21218]: sig_analog.c:3872 analog_fixup: New owner for channel 1 is DAHDI/3-1<MASQ>
[Apr 21 12:22:08] DEBUG[21218]: sig_analog.c:768 analog_update_conf: Updated conferencing on 1, with 0 conference users
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:4803 update_conf: Updated conferencing on 1, with 0 conference users
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:9285 dahdi_indicate: Requested indication 3 on channel DAHDI/3-1<MASQ>
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:6099 dahdi_hangup: dahdi_hangup(DAHDI/3-1<MASQ>)
[Apr 21 12:22:08] DEBUG[21218]: sig_analog.c:1268 analog_hangup: analog_hangup 1
[Apr 21 12:22:08] DEBUG[21218]: sig_analog.c:1291 analog_hangup: Hangup: channel: 1 index = 0, normal = 1, callwait = 0, thirdcall = 0
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:6668 dahdi_setoption: Set option TONE VERIFY, mode: OFF(0) on DAHDI/3-1<MASQ>
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:6678 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/3-1<MASQ>
[Apr 21 12:22:08] DEBUG[21218]: sig_analog.c:768 analog_update_conf: Updated conferencing on 1, with 0 conference users
-- Hanging up on 'DAHDI/3-1<MASQ>'
-- Hungup 'DAHDI/3-1<MASQ>'
[Apr 21 12:22:08] DEBUG[21218]: channel.c:5112 set_format: Set channel DAHDI/3-1 to write format slin
[Apr 21 12:22:08] DEBUG[21218]: channel.c:5112 set_format: Set channel DAHDI/3-1 to read format slin
[Apr 21 12:22:08] DEBUG[21218]: channel.c:6692 ast_do_masquerade: Putting channel DAHDI/3-1 in slin/slin formats
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:7493 dahdi_fixup: New owner for channel 3 is DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:4803 update_conf: Updated conferencing on 3, with 0 conference users
[Apr 21 12:22:08] DEBUG[21218]: sig_analog.c:3872 analog_fixup: New owner for channel 3 is DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21218]: sig_analog.c:768 analog_update_conf: Updated conferencing on 3, with 0 conference users
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:4803 update_conf: Updated conferencing on 3, with 0 conference users
[Apr 21 12:22:08] DEBUG[21218]: channel.c:6737 ast_do_masquerade: Released clone lock on 'DAHDI/1-1<ZOMBIE>'
[Apr 21 12:22:08] DEBUG[21218]: channel.c:6745 ast_do_masquerade: Done Masquerading DAHDI/3-1 (1)
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:9285 dahdi_indicate: Requested indication 26 on channel DAHDI/3-1
-- DAHDI/3-1 answered SIP/200-00000005
[Apr 21 12:22:08] DEBUG[21218]: chan_sip.c:6089 sip_answer: SIP answering channel: SIP/200-00000005
[Apr 21 12:22:08] DEBUG[21218]: chan_sip.c:11325 transmit_response_with_sdp: Setting framing from config on incoming call
[Apr 21 12:22:08] DEBUG[21218]: chan_sip.c:10953 add_sdp: ** Our capability: (g723) Video flag: True Text flag: True
[Apr 21 12:22:08] DEBUG[21218]: chan_sip.c:10954 add_sdp: ** Our prefcodec: (nothing)
[Apr 21 12:22:08] DEBUG[21225]: channel.c:3470 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
-- <DAHDI/3-1> Playing 'beep.slin' (language 'en')
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:9285 dahdi_indicate: Requested indication 20 on channel DAHDI/3-1
[Apr 21 12:22:08] DEBUG[21218]: channel.c:3157 ast_waitfor_nandfds: Thread 1218995344 Blocking 'DAHDI/3-1', already blocked by thread 1219241104 in procedure ast_waitfor_nandfds
[Apr 21 12:22:08] DEBUG[15610]: chan_sip.c:3831 __sip_ack: Stopping retransmission on '3c27c7f8e57e-t9iceszcrded@snom360' of Response 1: Match Found
[Apr 21 12:22:08] DEBUG[21218]: res_rtp_asterisk.c:1237 ast_rtp_write: Ooh, format changed from unknown to g723
[Apr 21 12:22:08] DEBUG[21218]: res_rtp_asterisk.c:1140 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x10d3a308'
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:9203 my_dahdi_write: Write returned -1 (Resource temporarily unavailable) on channel 3
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:9203 my_dahdi_write: Write returned -1 (Resource temporarily unavailable) on channel 3
[Apr 21 12:22:08] DEBUG[21225]: channel.c:3470 ast_settimeout: Scheduling timer at (364 requested / 364 actual) timer ticks per second
[Apr 21 12:22:08] DEBUG[21225]: channel.c:3470 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 21 12:22:08] DEBUG[21225]: channel.c:3470 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 21 12:22:08] DEBUG[21225]: channel.c:3470 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 21 12:22:08] DEBUG[21225]: channel.c:2805 ast_hangup: Hanging up zombie 'DAHDI/1-1<ZOMBIE>'
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:9203 my_dahdi_write: Write returned -1 (Resource temporarily unavailable) on channel 3
[Apr 21 12:22:08] DEBUG[21218]: chan_dahdi.c:9203 my_dahdi_write: Write returned -1 (Resource temporarily unavailable) on channel 3
[Apr 21 12:22:14] DEBUG[21218]: sig_analog.c:3465 analog_exception: analog_exception 3
[Apr 21 12:22:14] DEBUG[21218]: sig_analog.c:3559 analog_exception: Exception on 9, channel 3
[Apr 21 12:22:14] DEBUG[21218]: sig_analog.c:2618 __analog_handle_event: __analog_handle_event 3
[Apr 21 12:22:14] DEBUG[21218]: sig_analog.c:2645 __analog_handle_event: Got event ANALOG_EVENT_ONHOOK(1) on channel 3 (index 0)
[Apr 21 12:22:14] DEBUG[21218]: chan_dahdi.c:4891 dahdi_disable_ec: Disabled echo cancellation on channel 3
[Apr 21 12:22:14] DEBUG[21218]: channel.c:7044 ast_generic_bridge: Didn't get a frame from channel: DAHDI/3-1
[Apr 21 12:22:14] DEBUG[21218]: channel.c:7519 ast_channel_bridge: Bridge stops bridging channels SIP/200-00000005 and DAHDI/3-1
[Apr 21 12:22:14] DEBUG[21218]: channel.c:2801 ast_hangup: Hanging up channel 'DAHDI/3-1'
[Apr 21 12:22:14] DEBUG[21218]: chan_dahdi.c:6099 dahdi_hangup: dahdi_hangup(DAHDI/3-1)
[Apr 21 12:22:14] DEBUG[21218]: sig_analog.c:1268 analog_hangup: analog_hangup 3
[Apr 21 12:22:14] DEBUG[21218]: sig_analog.c:1291 analog_hangup: Hangup: channel: 3 index = 0, normal = 1, callwait = 0, thirdcall = 0
[Apr 21 12:22:14] DEBUG[21218]: chan_dahdi.c:6668 dahdi_setoption: Set option TONE VERIFY, mode: OFF(0) on DAHDI/3-1
[Apr 21 12:22:14] DEBUG[21218]: chan_dahdi.c:6678 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/3-1
[Apr 21 12:22:14] DEBUG[21218]: sig_analog.c:768 analog_update_conf: Updated conferencing on 3, with 0 conference users
-- Hanging up on 'DAHDI/3-1'
-- Hungup 'DAHDI/3-1'
[Apr 21 12:22:14] DEBUG[21218]: app_dial.c:2873 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Apr 21 12:22:14] DEBUG[21218]: pbx.c:4887 __ast_pbx_run: Spawn extension (from-internal,4001,1) exited non-zero on 'SIP/200-00000005'
== Spawn extension (from-internal, 4001, 1) exited non-zero on 'SIP/200-00000005'
[Apr 21 12:22:14] DEBUG[21218]: channel.c:2659 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/200-00000005'
[Apr 21 12:22:14] DEBUG[21218]: channel.c:2801 ast_hangup: Hanging up channel 'SIP/200-00000005'
[Apr 21 12:22:14] DEBUG[21218]: chan_sip.c:5886 sip_hangup: Hangup call SIP/200-00000005, SIP callid 3c27c7f8e57e-t9iceszcrded@snom360
[Apr 21 12:22:14] DEBUG[21218]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x10d3a308'
[Apr 21 12:22:14] DEBUG[15610]: chan_sip.c:3831 __sip_ack: Stopping retransmission on '3c27c7f8e57e-t9iceszcrded@snom360' of Request 102: Match Found
[Apr 21 12:22:14] DEBUG[15610]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x10d3a308'
[Apr 21 12:22:15] DEBUG[15610]: chan_sip.c:3831 __sip_ack: Stopping retransmission on '3c27c7f8e57e-t9iceszcrded@snom360' of Request 102: Match Not Found