[2012-01-13 10:06:58] DEBUG[27887] acl.c: For destination '10.252.0.254', our source address is '192.168.67.43'.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.67.43:5061
[2012-01-13 10:06:58] VERBOSE[27887] netsock.c:   == Using UDPTL CoS mark 5
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Setting NAT on UDPTL to Off
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Allocating new SIP dialog for 7f47c0472c69738411d1977e21cc5a0f@10.252.0.254 - INVITE (No RTP)
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2012-01-13 10:06:58] DEBUG[27887] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces"
[2012-01-13 10:06:58] DEBUG[27887] sip/reqresp_parser.c: Found SIP option: -replaces-
[2012-01-13 10:06:58] DEBUG[27887] sip/reqresp_parser.c: Matched SIP option: replaces
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Setting NAT on UDPTL to Off
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.252.0.254:5060
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Stopping retransmission on '7f47c0472c69738411d1977e21cc5a0f@10.252.0.254' of Response 102: Match Found
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Setting NAT on UDPTL to Off
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x92b04a8'
[2012-01-13 10:06:58] DEBUG[27887] res_rtp_asterisk.c: Allocated port 19622 for RTP instance '0x92b04a8'
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: RTP instance '0x92b04a8' is setup and ready to go
[2012-01-13 10:06:58] DEBUG[27887] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x92b04a8'
[2012-01-13 10:06:58] VERBOSE[27887] netsock2.c:   == Using SIP RTP CoS mark 5
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Setting NAT on RTP to Off
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Setting NAT on UDPTL to Off
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing session-level SDP o=root 30836 30837 IN IP4 10.252.0.254... UNSUPPORTED.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing session-level SDP c=IN IP4 10.252.0.254... OK.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Setting payload 8 based on m type on 0xb66a5e6c
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Setting payload 0 based on m type on 0xb66a5e6c
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Setting payload 18 based on m type on 0xb66a5e6c
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Setting payload 101 based on m type on 0xb66a5e6c
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Incorporating payload 0 on 0xb66a5e6c
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Incorporating payload 8 on 0xb66a5e6c
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Incorporating payload 18 on 0xb66a5e6c
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Incorporating payload 101 on 0xb66a5e6c
[2012-01-13 10:06:58] DEBUG[27887] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x92b04a8'
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Copying payload 0 from 0xb66a5e6c to 0x92b0654
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Copying payload 8 from 0xb66a5e6c to 0x92b0654
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Copying payload 18 from 0xb66a5e6c to 0x92b0654
[2012-01-13 10:06:58] DEBUG[27887] rtp_engine.c: Copying payload 101 from 0xb66a5e6c to 0x92b0654
[2012-01-13 10:06:58] DEBUG[27887] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x92b04a8'
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: We're settling with these formats: (alaw)
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Checking SIP call limits for device asterisk10
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Updating call counter for incoming call
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: *** Our native formats are (alaw)
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: *** Joint capabilities are (alaw)
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: *** Our capabilities are (alaw)
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: This channel will not be able to handle video.
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: build_route: Contact hop: <sip:098765@10.252.0.254>
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: SIP/asterisk10-00000000: New call is still down.... Trying...
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.252.0.254:5060
[2012-01-13 10:06:58] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for SIP - asterisk10
[2012-01-13 10:06:58] DEBUG[27881] chan_sip.c: Checking device state for peer asterisk10
[2012-01-13 10:06:58] DEBUG[27881] devicestate.c: Changing state for SIP/asterisk10 - state 1 (Not in use)
[2012-01-13 10:06:58] DEBUG[27881] devicestate.c: device 'SIP/asterisk10' state '1'
[2012-01-13 10:06:58] DEBUG[27899] pbx.c: Function result is '"Alex" <098765>'
[2012-01-13 10:06:58] DEBUG[27899] pbx.c: Launching 'NoOp'
[2012-01-13 10:06:58] VERBOSE[27899] pbx.c:     -- Executing [123456@to-office:1] NoOp("SIP/asterisk10-00000000", "Call from '"Alex" <098765>' to '123456'") in new stack
[2012-01-13 10:06:58] DEBUG[27899] pbx.c: Launching 'Set'
[2012-01-13 10:06:58] VERBOSE[27899] pbx.c:     -- Executing [123456@to-office:2] Set("SIP/asterisk10-00000000", "FAXOPT(gateway)=yes") in new stack
[2012-01-13 10:06:58] DEBUG[27899] res_fax.c: channel 'SIP/asterisk10-00000000' setting FAXOPT(gateway) to 'yes'
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup v21 detector, block_size=160
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup v21 detector, block_size=160
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup v21 detector, block_size=160
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup v21 detector, block_size=160
[2012-01-13 10:06:58] DEBUG[27899] res_fax.c: Attached T.38 gateway to channel SIP/asterisk10-00000000.
[2012-01-13 10:06:58] DEBUG[27899] pbx.c: Launching 'Dial'
[2012-01-13 10:06:58] VERBOSE[27899] pbx.c:     -- Executing [123456@to-office:3] Dial("SIP/asterisk10-00000000", "SIP/spa3102_line1,,Tt") in new stack
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: Asked to create a SIP channel with formats: (alaw)
[2012-01-13 10:06:58] VERBOSE[27899] netsock.c:   == Using UDPTL CoS mark 5
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: Allocating new SIP dialog for 28d017d35503e94577722c6b7c7df267@127.0.1.1:0 - INVITE (No RTP)
[2012-01-13 10:06:58] DEBUG[27899] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x92c0ed0'
[2012-01-13 10:06:58] DEBUG[27899] res_rtp_asterisk.c: Allocated port 14120 for RTP instance '0x92c0ed0'
[2012-01-13 10:06:58] DEBUG[27899] rtp_engine.c: RTP instance '0x92c0ed0' is setup and ready to go
[2012-01-13 10:06:58] DEBUG[27899] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x92c0ed0'
[2012-01-13 10:06:58] VERBOSE[27899] netsock2.c:   == Using SIP RTP CoS mark 5
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: Setting NAT on RTP to Off
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: Setting NAT on UDPTL to Off
[2012-01-13 10:06:58] DEBUG[27899] acl.c: For destination '172.16.50.135', our source address is '192.168.67.43'.
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.67.43:5061
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: *** Our native formats are (g729)
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: *** Joint capabilities are (nothing)
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: *** Our capabilities are (g729)
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: *** AST_CODEC_CHOOSE formats are g729
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: *** Our preferred formats from the incoming channel are (alaw)
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: This channel will not be able to handle video.
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2012-01-13 10:06:58] DEBUG[27899] dsp.c: Setup v21 detector, block_size=160
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable DIALEDTIME.
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable ANSWEREDTIME.
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable DIALEDPEERNAME.
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable DIALEDPEERNUMBER.
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable DIALSTATUS.
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable FAXPAGES.
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable FAXSTATUSSTRING.
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable FAXERROR.
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable FAXSTATUS.
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable SIPCALLID.
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable SIPDOMAIN.
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Not copying variable SIPURI.
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: Outgoing Call for spa3102_line1
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: Updating call counter for outgoing call
[2012-01-13 10:06:58] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for SIP - spa3102_line1
[2012-01-13 10:06:58] DEBUG[27881] chan_sip.c: Checking device state for peer spa3102_line1
[2012-01-13 10:06:58] DEBUG[27881] devicestate.c: Changing state for SIP/spa3102_line1 - state 6 (Ringing)
[2012-01-13 10:06:58] DEBUG[27881] devicestate.c: device 'SIP/spa3102_line1' state '6'
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: ** Our capability: (g729) Video flag: False Text flag: False
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: ** Our prefcodec: (alaw)
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: -- Done with adding codecs to SDP
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: Done building SDP. Settling with this capability: (g729)
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: Initializing initreq for method INVITE - callid 3d1644677572c4377c438cfe240f386f@192.168.67.43:5061
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 172.16.50.135:5060
[2012-01-13 10:06:58] VERBOSE[27899] app_dial.c:     -- Called SIP/spa3102_line1
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Set channel SIP/spa3102_line1-00000001 to read format slin
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Set channel SIP/asterisk10-00000000 to write format slin
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Set channel SIP/asterisk10-00000000 to read format slin
[2012-01-13 10:06:58] DEBUG[27899] channel.c: Set channel SIP/spa3102_line1-00000001 to write format slin
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3d1644677572c4377c438cfe240f386f@192.168.67.43:5061' Request 102: Found
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: SIP response 100 to standard invite
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3d1644677572c4377c438cfe240f386f@192.168.67.43:5061' Request 102: Found
[2012-01-13 10:06:58] DEBUG[27887] chan_sip.c: SIP response 180 to standard invite
[2012-01-13 10:06:58] VERBOSE[27899] app_dial.c:     -- SIP/spa3102_line1-00000001 is ringing
[2012-01-13 10:06:58] DEBUG[27899] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 10.252.0.254:5060
[2012-01-13 10:06:58] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for SIP - spa3102_line1
[2012-01-13 10:06:58] DEBUG[27881] chan_sip.c: Checking device state for peer spa3102_line1
[2012-01-13 10:06:58] DEBUG[27881] devicestate.c: Changing state for SIP/spa3102_line1 - state 6 (Ringing)
[2012-01-13 10:06:58] DEBUG[27881] devicestate.c: device 'SIP/spa3102_line1' state '6'
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Acked pending invite 102
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Stopping retransmission on '3d1644677572c4377c438cfe240f386f@192.168.67.43:5061' of Request 102: Match Found
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: SIP response 200 to standard invite
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Processing session-level SDP o=- 379932 379932 IN IP4 172.16.50.135... UNSUPPORTED.
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED.
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Processing session-level SDP c=IN IP4 172.16.50.135... OK.
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[2012-01-13 10:07:00] DEBUG[27887] rtp_engine.c: Setting payload 18 based on m type on 0xb66a5f8c
[2012-01-13 10:07:00] DEBUG[27887] rtp_engine.c: Setting payload 101 based on m type on 0xb66a5f8c
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK.
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED.
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK.
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2012-01-13 10:07:00] DEBUG[27887] rtp_engine.c: Incorporating payload 18 on 0xb66a5f8c
[2012-01-13 10:07:00] DEBUG[27887] rtp_engine.c: Incorporating payload 101 on 0xb66a5f8c
[2012-01-13 10:07:00] DEBUG[27887] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x92c0ed0'
[2012-01-13 10:07:00] DEBUG[27887] rtp_engine.c: Copying payload 18 from 0xb66a5f8c to 0x92c107c
[2012-01-13 10:07:00] DEBUG[27887] rtp_engine.c: Copying payload 101 from 0xb66a5f8c to 0x92c107c
[2012-01-13 10:07:00] DEBUG[27887] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x92c0ed0'
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: We're settling with these formats: (g729)
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: We have an owner, now see if we need to change this call
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Updating call counter for outgoing call
[2012-01-13 10:07:00] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for SIP - spa3102_line1
[2012-01-13 10:07:00] DEBUG[27881] chan_sip.c: Checking device state for peer spa3102_line1
[2012-01-13 10:07:00] DEBUG[27881] devicestate.c: Changing state for SIP/spa3102_line1 - state 3 (Busy)
[2012-01-13 10:07:00] DEBUG[27881] devicestate.c: device 'SIP/spa3102_line1' state '3'
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: build_route: Contact hop: spa3102_line1 <sip:spa3102_line1@172.16.50.135:5060>
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Trying to put 'ACK sip:spa' onto UDP socket destined for 172.16.50.135:5060
[2012-01-13 10:07:00] VERBOSE[27899] app_dial.c:     -- SIP/spa3102_line1-00000001 answered SIP/asterisk10-00000000
[2012-01-13 10:07:00] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for SIP - spa3102_line1
[2012-01-13 10:07:00] DEBUG[27881] chan_sip.c: Checking device state for peer spa3102_line1
[2012-01-13 10:07:00] DEBUG[27881] devicestate.c: Changing state for SIP/spa3102_line1 - state 3 (Busy)
[2012-01-13 10:07:00] DEBUG[27881] devicestate.c: device 'SIP/spa3102_line1' state '3'
[2012-01-13 10:07:00] DEBUG[27899] chan_sip.c: SIP answering channel: SIP/asterisk10-00000000
[2012-01-13 10:07:00] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:00] DEBUG[27899] chan_sip.c: Setting framing from config on incoming call
[2012-01-13 10:07:00] DEBUG[27899] chan_sip.c: ** Our capability: (alaw) Video flag: True Text flag: True
[2012-01-13 10:07:00] DEBUG[27899] chan_sip.c: ** Our prefcodec: (nothing)
[2012-01-13 10:07:00] DEBUG[27899] chan_sip.c: -- Done with adding codecs to SDP
[2012-01-13 10:07:00] DEBUG[27899] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[2012-01-13 10:07:00] DEBUG[27899] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.252.0.254:5060
[2012-01-13 10:07:00] DEBUG[27899] features.c: bridge answer set, chan answer set
[2012-01-13 10:07:00] DEBUG[27899] features.c: Removing dialed interfaces datastore on SIP/spa3102_line1-00000001 since we're bridging
[2012-01-13 10:07:00] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:00] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:00] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for SIP - asterisk10
[2012-01-13 10:07:00] DEBUG[27881] chan_sip.c: Checking device state for peer asterisk10
[2012-01-13 10:07:00] DEBUG[27881] devicestate.c: Changing state for SIP/asterisk10 - state 1 (Not in use)
[2012-01-13 10:07:00] DEBUG[27881] devicestate.c: device 'SIP/asterisk10' state '1'
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2012-01-13 10:07:00] DEBUG[27887] chan_sip.c: Stopping retransmission on '7f47c0472c69738411d1977e21cc5a0f@10.252.0.254' of Response 103: Match Found
[2012-01-13 10:07:00] WARNING[27899] dsp.c: Inband DTMF is not supported on codec g729. Use RFC2833
[2012-01-13 10:07:00] DEBUG[27899] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw
[2012-01-13 10:07:00] DEBUG[27899] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160
[2012-01-13 10:07:00] DEBUG[27899] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x92b04a8'
[2012-01-13 10:07:00] DEBUG[27899] res_rtp_asterisk.c: Ooh, format changed from unknown to g729
[2012-01-13 10:07:00] DEBUG[27899] res_rtp_asterisk.c: Created smoother: format: g729 ms: 20 len: 20
[2012-01-13 10:07:01] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 35 (#), at 172.16.50.135:16404
[2012-01-13 10:07:01] DTMF[27899] channel.c: DTMF begin '#' received on SIP/spa3102_line1-00000001
[2012-01-13 10:07:01] DTMF[27899] channel.c: DTMF begin passthrough '#' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:01] DEBUG[27899] channel.c: Got DTMF begin on channel (SIP/spa3102_line1-00000001)
[2012-01-13 10:07:01] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:01] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:01] DEBUG[27899] channel.c: Bridge stops bridging channels SIP/asterisk10-00000000 and SIP/spa3102_line1-00000001
[2012-01-13 10:07:01] DEBUG[27899] features.c: Not passing DTMF through, since it may be a feature code
[2012-01-13 10:07:01] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:01] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:01] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 35 (#), at 172.16.50.135:16404
[2012-01-13 10:07:01] DTMF[27899] channel.c: DTMF end '#' received on SIP/spa3102_line1-00000001, duration 110 ms
[2012-01-13 10:07:01] DTMF[27899] channel.c: DTMF end accepted with begin '#' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:01] DTMF[27899] channel.c: DTMF end '#' detected to have actual duration 60 on the wire, emulation will be triggered on SIP/spa3102_line1-00000001
[2012-01-13 10:07:01] DTMF[27899] channel.c: DTMF end '#' has duration 60 but want minimum 80, emulating on SIP/spa3102_line1-00000001
[2012-01-13 10:07:01] DTMF[27899] channel.c: DTMF end emulation of '#' queued on SIP/spa3102_line1-00000001
[2012-01-13 10:07:01] DEBUG[27899] channel.c: Got DTMF end on channel (SIP/spa3102_line1-00000001)
[2012-01-13 10:07:01] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:01] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:01] DEBUG[27899] channel.c: Bridge stops bridging channels SIP/asterisk10-00000000 and SIP/spa3102_line1-00000001
[2012-01-13 10:07:01] DEBUG[27899] features.c: Feature interpret: chan=SIP/asterisk10-00000000, peer=SIP/spa3102_line1-00000001, code=#, sense=2, features=2, dynamic=#
[2012-01-13 10:07:01] DEBUG[27899] features.c: Set feature timer to 1000 ms
[2012-01-13 10:07:01] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:01] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:02] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 50 (2), at 172.16.50.135:16404
[2012-01-13 10:07:02] DTMF[27899] channel.c: DTMF begin '2' received on SIP/spa3102_line1-00000001
[2012-01-13 10:07:02] DTMF[27899] channel.c: DTMF begin passthrough '2' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Got DTMF begin on channel (SIP/spa3102_line1-00000001)
[2012-01-13 10:07:02] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:02] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Bridge stops bridging channels SIP/asterisk10-00000000 and SIP/spa3102_line1-00000001
[2012-01-13 10:07:02] DEBUG[27899] features.c: Not passing DTMF through, since it may be a feature code
[2012-01-13 10:07:02] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:02] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:02] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 50 (2), at 172.16.50.135:16404
[2012-01-13 10:07:02] DTMF[27899] channel.c: DTMF end '2' received on SIP/spa3102_line1-00000001, duration 90 ms
[2012-01-13 10:07:02] DTMF[27899] channel.c: DTMF end accepted with begin '2' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:02] DTMF[27899] channel.c: DTMF end '2' detected to have actual duration 50 on the wire, emulation will be triggered on SIP/spa3102_line1-00000001
[2012-01-13 10:07:02] DTMF[27899] channel.c: DTMF end '2' has duration 50 but want minimum 80, emulating on SIP/spa3102_line1-00000001
[2012-01-13 10:07:02] DTMF[27899] channel.c: DTMF end emulation of '2' queued on SIP/spa3102_line1-00000001
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Got DTMF end on channel (SIP/spa3102_line1-00000001)
[2012-01-13 10:07:02] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:02] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Bridge stops bridging channels SIP/asterisk10-00000000 and SIP/spa3102_line1-00000001
[2012-01-13 10:07:02] DEBUG[27899] features.c: Feature interpret: chan=SIP/asterisk10-00000000, peer=SIP/spa3102_line1-00000001, code=#2, sense=2, features=2, dynamic=#
[2012-01-13 10:07:02] DEBUG[27899] features.c: Feature detected: fname=Attended Transfer sname=atxfer exten=#2
[2012-01-13 10:07:02] DEBUG[27899] features.c: Executing Attended Transfer SIP/asterisk10-00000000, SIP/spa3102_line1-00000001 (sense=2)
[2012-01-13 10:07:02] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:02] VERBOSE[27899] res_musiconhold.c:     -- Started music on hold, class 'default', on SIP/asterisk10-00000000
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2012-01-13 10:07:02] VERBOSE[27899] file.c:     -- <SIP/spa3102_line1-00000001> Playing 'pbx-transfer.slin' (language 'ru')
[2012-01-13 10:07:02] DEBUG[27905] res_musiconhold.c: SIP/asterisk10-00000000 Opened file 0 '/var/lib/asterisk/moh/macroform-the_simplicity'
[2012-01-13 10:07:02] DEBUG[27905] res_rtp_asterisk.c: Difference is 904, ms is 133
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Scheduling timer at (98 requested / 98 actual) timer ticks per second
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2012-01-13 10:07:02] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 50 (2), at 172.16.50.135:16404
[2012-01-13 10:07:02] DTMF[27899] channel.c: DTMF begin '2' received on SIP/spa3102_line1-00000001
[2012-01-13 10:07:02] DTMF[27899] channel.c: DTMF begin ignored '2' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:02] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 50 (2), at 172.16.50.135:16404
[2012-01-13 10:07:02] DTMF[27899] channel.c: DTMF end '2' received on SIP/spa3102_line1-00000001, duration 90 ms
[2012-01-13 10:07:02] DTMF[27899] channel.c: DTMF end passthrough '2' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:02] DEBUG[27899] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2012-01-13 10:07:03] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 51 (3), at 172.16.50.135:16404
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF begin '3' received on SIP/spa3102_line1-00000001
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF begin ignored '3' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:03] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 51 (3), at 172.16.50.135:16404
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF end '3' received on SIP/spa3102_line1-00000001, duration 90 ms
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF end passthrough '3' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:03] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 52 (4), at 172.16.50.135:16404
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF begin '4' received on SIP/spa3102_line1-00000001
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF begin ignored '4' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:03] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 52 (4), at 172.16.50.135:16404
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF end '4' received on SIP/spa3102_line1-00000001, duration 110 ms
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF end passthrough '4' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:03] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 53 (5), at 172.16.50.135:16404
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF begin '5' received on SIP/spa3102_line1-00000001
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF begin ignored '5' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:03] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 53 (5), at 172.16.50.135:16404
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF end '5' received on SIP/spa3102_line1-00000001, duration 110 ms
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF end passthrough '5' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:03] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 54 (6), at 172.16.50.135:16404
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF begin '6' received on SIP/spa3102_line1-00000001
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF begin ignored '6' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:03] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 54 (6), at 172.16.50.135:16404
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF end '6' received on SIP/spa3102_line1-00000001, duration 90 ms
[2012-01-13 10:07:03] DTMF[27899] channel.c: DTMF end passthrough '6' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:04] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 55 (7), at 172.16.50.135:16404
[2012-01-13 10:07:04] DTMF[27899] channel.c: DTMF begin '7' received on SIP/spa3102_line1-00000001
[2012-01-13 10:07:04] DTMF[27899] channel.c: DTMF begin ignored '7' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:04] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 55 (7), at 172.16.50.135:16404
[2012-01-13 10:07:04] DTMF[27899] channel.c: DTMF end '7' received on SIP/spa3102_line1-00000001, duration 90 ms
[2012-01-13 10:07:04] DTMF[27899] channel.c: DTMF end passthrough '7' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:04] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 35 (#), at 172.16.50.135:16404
[2012-01-13 10:07:04] DTMF[27899] channel.c: DTMF begin '#' received on SIP/spa3102_line1-00000001
[2012-01-13 10:07:04] DTMF[27899] channel.c: DTMF begin ignored '#' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:04] DEBUG[27899] res_rtp_asterisk.c: Sending dtmf: 35 (#), at 172.16.50.135:16404
[2012-01-13 10:07:04] DTMF[27899] channel.c: DTMF end '#' received on SIP/spa3102_line1-00000001, duration 110 ms
[2012-01-13 10:07:04] DTMF[27899] channel.c: DTMF end passthrough '#' on SIP/spa3102_line1-00000001
[2012-01-13 10:07:04] DEBUG[27899] channel.c: Not copying variable BRIDGEPVTCALLID.
[2012-01-13 10:07:04] DEBUG[27899] channel.c: Not copying variable BRIDGEPEER.
[2012-01-13 10:07:04] DEBUG[27899] channel.c: Not copying variable DIALEDPEERNUMBER.
[2012-01-13 10:07:04] DEBUG[27899] channel.c: Not copying variable SIPCALLID.
[2012-01-13 10:07:04] DEBUG[27906] pbx.c: Function result is '"" <765432>'
[2012-01-13 10:07:04] DEBUG[27906] pbx.c: Launching 'NoOp'
[2012-01-13 10:07:04] VERBOSE[27906] pbx.c:     -- Executing [234567@from-gordeev:1] NoOp("Local/234567@from-gordeev-1fdc;2", "Call from '"" <765432>' to '234567'") in new stack
[2012-01-13 10:07:04] DEBUG[27906] pbx.c: Launching 'Set'
[2012-01-13 10:07:04] VERBOSE[27906] pbx.c:     -- Executing [234567@from-gordeev:2] Set("Local/234567@from-gordeev-1fdc;2", "FAXOPT(gateway)=yes") in new stack
[2012-01-13 10:07:04] DEBUG[27906] res_fax.c: channel 'Local/234567@from-gordeev-1fdc;2' setting FAXOPT(gateway) to 'yes'
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup v21 detector, block_size=160
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup v21 detector, block_size=160
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup v21 detector, block_size=160
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2012-01-13 10:07:04] DEBUG[27906] dsp.c: Setup v21 detector, block_size=160
[2012-01-13 10:07:04] DEBUG[27906] res_fax.c: Attached T.38 gateway to channel Local/234567@from-gordeev-1fdc;2.
[2012-01-13 10:07:04] DEBUG[27906] pbx.c: Launching 'Dial'
[2012-01-13 10:07:04] VERBOSE[27906] pbx.c:     -- Executing [234567@from-gordeev:3] Dial("Local/234567@from-gordeev-1fdc;2", "SIP/asterisk10/234567,,Tt") in new stack
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: Asked to create a SIP channel with formats: (g729)
[2012-01-13 10:07:04] VERBOSE[27906] netsock.c:   == Using UDPTL CoS mark 5
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: Allocating new SIP dialog for 69063d377def756a6c766f0b50d5be05@127.0.1.1:0 - INVITE (No RTP)
[2012-01-13 10:07:04] DEBUG[27906] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x930c7a8'
[2012-01-13 10:07:04] DEBUG[27906] res_rtp_asterisk.c: Allocated port 17796 for RTP instance '0x930c7a8'
[2012-01-13 10:07:04] DEBUG[27906] rtp_engine.c: RTP instance '0x930c7a8' is setup and ready to go
[2012-01-13 10:07:04] DEBUG[27906] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x930c7a8'
[2012-01-13 10:07:04] VERBOSE[27906] netsock2.c:   == Using SIP RTP CoS mark 5
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: Setting NAT on RTP to Off
[2012-01-13 10:07:04] DEBUG[27906] acl.c: For destination '10.252.0.254', our source address is '192.168.67.43'.
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.67.43:5061
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: *** Our native formats are (alaw)
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: *** Joint capabilities are (nothing)
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: *** Our capabilities are (alaw)
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: *** Our preferred formats from the incoming channel are (g729)
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: This channel will not be able to handle video.
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Not copying variable DIALEDTIME.
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Not copying variable ANSWEREDTIME.
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Not copying variable DIALEDPEERNAME.
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Not copying variable DIALEDPEERNUMBER.
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Not copying variable DIALSTATUS.
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Not copying variable FAXPAGES.
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Not copying variable FAXSTATUSSTRING.
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Not copying variable FAXERROR.
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Not copying variable FAXSTATUS.
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Not copying variable TRANSFERERNAME.
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: Outgoing Call for 234567
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: Updating call counter for outgoing call
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: False
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: ** Our prefcodec: (g729)
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: -- Done with adding codecs to SDP
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: Initializing initreq for method INVITE - callid 11abbcef1f32e12e34bc287e5c53b1b8@192.168.67.43:5061
[2012-01-13 10:07:04] DEBUG[27906] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.252.0.254:5060
[2012-01-13 10:07:04] VERBOSE[27906] app_dial.c:     -- Called SIP/asterisk10/234567
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Set channel SIP/asterisk10-00000002 to read format slin
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Acked pending invite 102
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Stopping retransmission on '11abbcef1f32e12e34bc287e5c53b1b8@192.168.67.43:5061' of Request 102: Match Found
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: SIP response 407 to standard invite
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Trying to put 'ACK sip:234' onto UDP socket destined for 10.252.0.254:5060
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Auth attempt 1 on INVITE
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: False
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: ** Our prefcodec: (g729)
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: -- Done with adding codecs to SDP
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.252.0.254:5060
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Set channel Local/234567@from-gordeev-1fdc;2 to write format slin
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '11abbcef1f32e12e34bc287e5c53b1b8@192.168.67.43:5061' Request 103: Found
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: SIP response 100 to standard invite
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Set channel Local/234567@from-gordeev-1fdc;2 to read format slin
[2012-01-13 10:07:04] DEBUG[27906] channel.c: Set channel SIP/asterisk10-00000002 to write format slin
[2012-01-13 10:07:04] WARNING[27899] channel.c: Codec mismatch on channel Local/234567@from-gordeev-1fdc;1 setting write format to slin from g729 native formats (g729)
[2012-01-13 10:07:04] DEBUG[27899] channel.c: Set channel Local/234567@from-gordeev-1fdc;1 to write format slin
[2012-01-13 10:07:04] DEBUG[27906] res_rtp_asterisk.c: No remote address on RTP instance '0x930c7a8' so dropping frame
[2012-01-13 10:07:04] DEBUG[27906] res_rtp_asterisk.c: No remote address on RTP instance '0x930c7a8' so dropping frame
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '11abbcef1f32e12e34bc287e5c53b1b8@192.168.67.43:5061' Request 103: Found
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: SIP response 100 to standard invite
[2012-01-13 10:07:04] DEBUG[27906] res_rtp_asterisk.c: No remote address on RTP instance '0x930c7a8' so dropping frame
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '11abbcef1f32e12e34bc287e5c53b1b8@192.168.67.43:5061' Request 103: Found
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: SIP response 180 to standard invite
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: build_route: Contact hop: <sip:234567@10.252.0.254>
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '11abbcef1f32e12e34bc287e5c53b1b8@192.168.67.43:5061' Request 103: Found
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: SIP response 183 to standard invite
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: build_route: Retaining previous route: <sip:234567@10.252.0.254>
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Processing session-level SDP o=root 30836 30836 IN IP4 10.252.0.254... UNSUPPORTED.
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED.
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Processing session-level SDP c=IN IP4 10.252.0.254... OK.
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[2012-01-13 10:07:04] DEBUG[27887] rtp_engine.c: Setting payload 8 based on m type on 0xb66a5f8c
[2012-01-13 10:07:04] DEBUG[27887] rtp_engine.c: Setting payload 101 based on m type on 0xb66a5f8c
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2012-01-13 10:07:04] DEBUG[27887] rtp_engine.c: Incorporating payload 8 on 0xb66a5f8c
[2012-01-13 10:07:04] DEBUG[27887] rtp_engine.c: Incorporating payload 101 on 0xb66a5f8c
[2012-01-13 10:07:04] DEBUG[27887] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x930c7a8'
[2012-01-13 10:07:04] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for SIP - asterisk10
[2012-01-13 10:07:04] DEBUG[27881] chan_sip.c: Checking device state for peer asterisk10
[2012-01-13 10:07:04] DEBUG[27881] devicestate.c: Changing state for SIP/asterisk10 - state 1 (Not in use)
[2012-01-13 10:07:04] DEBUG[27881] devicestate.c: device 'SIP/asterisk10' state '1'
[2012-01-13 10:07:04] DEBUG[27887] rtp_engine.c: Copying payload 8 from 0xb66a5f8c to 0x930c954
[2012-01-13 10:07:04] DEBUG[27887] rtp_engine.c: Copying payload 101 from 0xb66a5f8c to 0x930c954
[2012-01-13 10:07:04] DEBUG[27887] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x930c7a8'
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: We're settling with these formats: (alaw)
[2012-01-13 10:07:04] DEBUG[27887] chan_sip.c: We have an owner, now see if we need to change this call
[2012-01-13 10:07:04] VERBOSE[27906] app_dial.c:     -- SIP/asterisk10-00000002 is ringing
[2012-01-13 10:07:04] VERBOSE[27906] app_dial.c:     -- SIP/asterisk10-00000002 is making progress passing it to Local/234567@from-gordeev-1fdc;2
[2012-01-13 10:07:04] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for Local - 234567@from-gordeev
[2012-01-13 10:07:04] DEBUG[27881] chan_local.c: Checking if extension 234567@from-gordeev exists (devicestate)
[2012-01-13 10:07:04] DEBUG[27881] devicestate.c: Changing state for Local/234567@from-gordeev - state 2 (In use)
[2012-01-13 10:07:04] DEBUG[27881] devicestate.c: device 'Local/234567@from-gordeev' state '2'
[2012-01-13 10:07:04] VERBOSE[27899] features.c:     -- Local/234567@from-gordeev-1fdc;1 is ringing
[2012-01-13 10:07:04] DEBUG[27899] channel.c: Driver for channel 'SIP/spa3102_line1-00000001' does not support indication 3, emulating it
[2012-01-13 10:07:04] DEBUG[27899] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2012-01-13 10:07:04] DEBUG[27899] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2012-01-13 10:07:04] DEBUG[27906] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw
[2012-01-13 10:07:04] DEBUG[27906] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Acked pending invite 103
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Stopping retransmission on '11abbcef1f32e12e34bc287e5c53b1b8@192.168.67.43:5061' of Request 103: Match Found
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: SIP response 200 to standard invite
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Processing session-level SDP o=root 30836 30837 IN IP4 10.252.0.254... UNSUPPORTED.
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED.
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Processing session-level SDP c=IN IP4 10.252.0.254... OK.
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[2012-01-13 10:07:06] DEBUG[27887] rtp_engine.c: Setting payload 8 based on m type on 0xb66a5f8c
[2012-01-13 10:07:06] DEBUG[27887] rtp_engine.c: Setting payload 101 based on m type on 0xb66a5f8c
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2012-01-13 10:07:06] DEBUG[27887] rtp_engine.c: Incorporating payload 8 on 0xb66a5f8c
[2012-01-13 10:07:06] DEBUG[27887] rtp_engine.c: Incorporating payload 101 on 0xb66a5f8c
[2012-01-13 10:07:06] DEBUG[27887] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x930c7a8'
[2012-01-13 10:07:06] DEBUG[27887] rtp_engine.c: Copying payload 8 from 0xb66a5f8c to 0x930c954
[2012-01-13 10:07:06] DEBUG[27887] rtp_engine.c: Copying payload 101 from 0xb66a5f8c to 0x930c954
[2012-01-13 10:07:06] DEBUG[27887] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x930c7a8'
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: We're settling with these formats: (alaw)
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: We have an owner, now see if we need to change this call
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Updating call counter for outgoing call
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: build_route: Retaining previous route: <sip:234567@10.252.0.254>
[2012-01-13 10:07:06] DEBUG[27887] chan_sip.c: Trying to put 'ACK sip:234' onto UDP socket destined for 10.252.0.254:5060
[2012-01-13 10:07:06] VERBOSE[27906] app_dial.c:     -- SIP/asterisk10-00000002 answered Local/234567@from-gordeev-1fdc;2
[2012-01-13 10:07:06] DEBUG[27906] features.c: bridge answer set, chan answer set
[2012-01-13 10:07:06] DEBUG[27906] features.c: Removing dialed interfaces datastore on SIP/asterisk10-00000002 since we're bridging
[2012-01-13 10:07:06] DEBUG[27906] res_fax.c: not starting gateway for Local/234567@from-gordeev-1fdc;2 and SIP/asterisk10-00000002; neither channel supports T.38
[2012-01-13 10:07:06] DEBUG[27906] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:06] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for SIP - asterisk10
[2012-01-13 10:07:06] DEBUG[27881] chan_sip.c: Checking device state for peer asterisk10
[2012-01-13 10:07:06] DEBUG[27881] devicestate.c: Changing state for SIP/asterisk10 - state 1 (Not in use)
[2012-01-13 10:07:06] DEBUG[27881] devicestate.c: device 'SIP/asterisk10' state '1'
[2012-01-13 10:07:06] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for Local - 234567@from-gordeev
[2012-01-13 10:07:06] DEBUG[27881] chan_local.c: Checking if extension 234567@from-gordeev exists (devicestate)
[2012-01-13 10:07:06] DEBUG[27881] devicestate.c: Changing state for Local/234567@from-gordeev - state 2 (In use)
[2012-01-13 10:07:06] DEBUG[27881] devicestate.c: device 'Local/234567@from-gordeev' state '2'
[2012-01-13 10:07:06] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for Local - 234567@from-gordeev
[2012-01-13 10:07:06] DEBUG[27881] chan_local.c: Checking if extension 234567@from-gordeev exists (devicestate)
[2012-01-13 10:07:06] DEBUG[27881] devicestate.c: Changing state for Local/234567@from-gordeev - state 2 (In use)
[2012-01-13 10:07:06] DEBUG[27881] devicestate.c: device 'Local/234567@from-gordeev' state '2'
[2012-01-13 10:07:06] DEBUG[27899] features.c: Dial party C result: newchan:1, outstate:4
[2012-01-13 10:07:06] DEBUG[27899] features.c: Actually doing an attended transfer.
[2012-01-13 10:07:06] DEBUG[27899] channel.c: Set channel SIP/spa3102_line1-00000001 to read format g729
[2012-01-13 10:07:06] DEBUG[27899] channel.c: Set channel Local/234567@from-gordeev-1fdc;1 to write format g729
[2012-01-13 10:07:06] DEBUG[27899] channel.c: Set channel SIP/spa3102_line1-00000001 to write format g729
[2012-01-13 10:07:06] DEBUG[27899] features.c: bridge answer set, chan answer set
[2012-01-13 10:07:06] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:06] DEBUG[27906] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:06] DEBUG[27899] channel.c: Got a FRAME_CONTROL (-1) frame on channel Local/234567@from-gordeev-1fdc;1
[2012-01-13 10:07:06] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:06] DEBUG[27906] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:06] DEBUG[27899] channel.c: Bridge stops bridging channels SIP/spa3102_line1-00000001 and Local/234567@from-gordeev-1fdc;1
[2012-01-13 10:07:06] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:06] DEBUG[27906] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:06] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:08] DEBUG[27887] chan_sip.c: Auto destroying SIP dialog '031fa46a2d21b33c656823fa0ffac291@10.252.0.254'
[2012-01-13 10:07:08] DEBUG[27887] chan_sip.c: Destroying SIP dialog 031fa46a2d21b33c656823fa0ffac291@10.252.0.254
[2012-01-13 10:07:08] DEBUG[27887] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[2012-01-13 10:07:08] DEBUG[27887] chan_sip.c: Setting SIP_ALREADYGONE on dialog 3d1644677572c4377c438cfe240f386f@192.168.67.43:5061
[2012-01-13 10:07:08] DEBUG[27887] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x92c0ed0'
[2012-01-13 10:07:08] DEBUG[27887] chan_sip.c: Received bye, issuing owner hangup
[2012-01-13 10:07:08] DEBUG[27887] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.16.50.135:5060
[2012-01-13 10:07:08] DEBUG[27899] channel.c: Didn't get a frame from channel: SIP/spa3102_line1-00000001
[2012-01-13 10:07:08] DEBUG[27899] channel.c: Bridge stops bridging channels SIP/spa3102_line1-00000001 and Local/234567@from-gordeev-1fdc;1
[2012-01-13 10:07:08] DEBUG[27899] channel.c: Set channel Local/234567@from-gordeev-1fdc;1 to write format slin
[2012-01-13 10:07:08] DEBUG[27899] channel.c: Set channel Local/234567@from-gordeev-1fdc;1 to read format slin
[2012-01-13 10:07:08] DEBUG[27899] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:08] VERBOSE[27899] res_musiconhold.c:     -- Stopped music on hold on SIP/asterisk10-00000000
[2012-01-13 10:07:08] DEBUG[27899] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2012-01-13 10:07:08] DEBUG[27906] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Planning to masquerade channel SIP/asterisk10-00000000 into the structure of Transfered/SIP/asterisk10-00000000
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Done planning to masquerade channel SIP/asterisk10-00000000 into the structure of Transfered/SIP/asterisk10-00000000
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Actually Masquerading SIP/asterisk10-00000000(6) into the structure of Transfered/SIP/asterisk10-00000000(6)
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Set channel SIP/asterisk10-00000000 to write format slin
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Set channel SIP/asterisk10-00000000 to read format slin
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Putting channel SIP/asterisk10-00000000 in slin/slin formats
[2012-01-13 10:07:09] DEBUG[27899] chan_sip.c: SIP Fixup: New owner for dialogue 7f47c0472c69738411d1977e21cc5a0f@10.252.0.254: SIP/asterisk10-00000000 (Old parent: Transfered/SIP/asterisk10-00000000<ZOMBIE>)
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Driver for channel 'SIP/asterisk10-00000000' does not support indication 3, emulating it
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Released clone lock on 'Transfered/SIP/asterisk10-00000000<ZOMBIE>'
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Done Masquerading SIP/asterisk10-00000000 (6)
[2012-01-13 10:07:09] DEBUG[27899] res_rtp_asterisk.c: Changing ssrc from 1019936080 to 1637275970 due to a source change
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second

[2012-01-13 10:07:09] VERBOSE[27899] file.c:     -- <Local/234567@from-gordeev-1fdc;1> Playing 'beep.slin' (language 'ru')
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Scheduling timer at (364 requested / 100 actual) timer ticks per second
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2012-01-13 10:07:09] DEBUG[27899] channel.c: Hanging up channel 'SIP/spa3102_line1-00000001'
[2012-01-13 10:07:09] DEBUG[27899] chan_sip.c: Hanging up zombie call. Be scared.
[2012-01-13 10:07:09] DEBUG[27899] chan_sip.c: Updating call counter for outgoing call
[2012-01-13 10:07:09] DEBUG[27881] devicestate.c: No provider found, checking channel drivers for SIP - spa3102_line1
[2012-01-13 10:07:09] DEBUG[27881] chan_sip.c: Checking device state for peer spa3102_line1
[2012-01-13 10:07:09] DEBUG[27881] devicestate.c: Changing state for SIP/spa3102_line1 - state 1 (Not in use)
[2012-01-13 10:07:09] DEBUG[27881] devicestate.c: device 'SIP/spa3102_line1' state '1'

Disconnected from Asterisk server
Executing last minute cleanups
Asterisk ending (0).
root@alex:/etc/asterisk/config# Asterisk ended with exit status 139
Asterisk exited on signal 11.
Automatically restarting Asterisk.