[Apr 13 11:36:28] DEBUG[17071] chan_sip.c: = Looking for Call ID: d32edeab-0e61-496a-8218-ae48b028161c (Checking From) --From tag 5a9d10c2-0c90-4461-aafc-6831e8a21ebc --To-tag [Apr 13 11:36:28] DEBUG[17071] acl.c: For destination '192.168.7.96', our source address is '192.168.0.172'. [Apr 13 11:36:28] DEBUG[17071] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.0.177:5060 [Apr 13 11:36:28] DEBUG[17071] netsock2.c: Splitting '172.16.0.101:38790' into... [Apr 13 11:36:28] DEBUG[17071] netsock2.c: ...host '172.16.0.101' and port '38790'. [Apr 13 11:36:28] DEBUG[17071] chan_sip.c: NAT detected for 172.16.0.101 / 192.168.7.96 [Apr 13 11:36:28] DEBUG[17071] chan_sip.c: Allocating new SIP dialog for d32edeab-0e61-496a-8218-ae48b028161c - INVITE (No RTP) [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Apr 13 11:36:28] DEBUG[17071][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, norefersub, gruu" [Apr 13 11:36:28] DEBUG[17071][C-00000001] sip/reqresp_parser.c: Found SIP option: -replaces- [Apr 13 11:36:28] DEBUG[17071][C-00000001] sip/reqresp_parser.c: Matched SIP option: replaces [Apr 13 11:36:28] DEBUG[17071][C-00000001] sip/reqresp_parser.c: Found SIP option: -norefersub- [Apr 13 11:36:28] DEBUG[17071][C-00000001] sip/reqresp_parser.c: Matched SIP option: norefersub [Apr 13 11:36:28] DEBUG[17071][C-00000001] sip/reqresp_parser.c: Found SIP option: -gruu- [Apr 13 11:36:28] DEBUG[17071][C-00000001] sip/reqresp_parser.c: Matched SIP option: gruu [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: Splitting '172.16.0.101:38790' into... [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: ...host '172.16.0.101' and port '38790'. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: NAT detected for 172.16.0.101 / 192.168.7.96 [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: Splitting '192.168.0.177' into... [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: ...host '192.168.0.177' and port ''. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.7.96:38790 [Apr 13 11:36:28] DEBUG[17071] chan_sip.c: = Looking for Call ID: d32edeab-0e61-496a-8218-ae48b028161c (Checking From) --From tag 5a9d10c2-0c90-4461-aafc-6831e8a21ebc --To-tag as1638cd04 [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Stopping retransmission on 'd32edeab-0e61-496a-8218-ae48b028161c' of Response 19573: Match Found [Apr 13 11:36:28] DEBUG[17071] chan_sip.c: = Looking for Call ID: d32edeab-0e61-496a-8218-ae48b028161c (Checking From) --From tag 5a9d10c2-0c90-4461-aafc-6831e8a21ebc --To-tag [Apr 13 11:36:28] DEBUG[17071] netsock2.c: Splitting '192.168.0.177' into... [Apr 13 11:36:28] DEBUG[17071] netsock2.c: ...host '192.168.0.177' and port ''. [Apr 13 11:36:28] DEBUG[17071] netsock2.c: Splitting '192.168.0.177' into... [Apr 13 11:36:28] DEBUG[17071] netsock2.c: ...host '192.168.0.177' and port ''. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: Splitting '172.16.0.101:38790' into... [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: ...host '172.16.0.101' and port '38790'. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: NAT detected for 172.16.0.101 / 192.168.7.96 [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: Splitting '192.168.0.177' into... [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: ...host '192.168.0.177' and port ''. [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f1a00043748' [Apr 13 11:36:28] DEBUG[17071][C-00000001] res_rtp_asterisk.c: Allocated port 19450 for RTP instance '0x7f1a00043748' [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: Splitting '192.168.0.172' into... [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: ...host '192.168.0.172' and port ''. [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: Splitting '192.168.0.177' into... [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: ...host '192.168.0.177' and port ''. [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: RTP instance '0x7f1a00043748' is setup and ready to go [Apr 13 11:36:28] DEBUG[17071][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f1a00043748' [Apr 13 11:36:28] VERBOSE[17071][C-00000001] netsock2.c: Using SIP RTP TOS bits 184 [Apr 13 11:36:28] VERBOSE[17071][C-00000001] netsock2.c: Using SIP RTP CoS mark 5 [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Setting NAT on RTP to On [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing session-level SDP o=- 3701061388 3701061388 IN IP4 192.168.7.96... OK. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing session-level SDP s=Blink 3.0.2 (Linux)... UNSUPPORTED OR FAILED. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: Setting payload 113 (0x7f1a000259b8) based on m type on 0x7f19d1963bf0 [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: Setting payload 9 (0x7f1a00040968) based on m type on 0x7f19d1963bf0 [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: Setting payload 0 (0x7f1a000519b8) based on m type on 0x7f19d1963bf0 [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: Setting payload 8 (0x7f1a0001e5f8) based on m type on 0x7f19d1963bf0 [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: Setting payload 101 (0x7f1a0005b368) based on m type on 0x7f19d1963bf0 [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: Splitting '192.168.7.96' into... [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: ...host '192.168.7.96' and port ''. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 192.168.7.96... OK. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtcp:50029... UNSUPPORTED OR FAILED. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:113 opus/48000/2... OK. [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: Unsetting payload 113 on 0x7f19d1963bf0 [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:113 useinbandfec=1... UNSUPPORTED OR FAILED. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=zrtp-hash:1.10 bf13afed8d17fb938ce419b6f1218ec17f9e4f8f0d2c36e9fcf7ec2f8d99eddf... UNSUPPORTED OR FAILED. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Apr 13 11:36:28] DEBUG[17071][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f1a00043748' [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: Copying payload 0 (0x7f1a00040968) from 0x7f19d1963bf0 to 0x7f1a00043888 [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: Copying payload 8 (0x7f1a000519b8) from 0x7f19d1963bf0 to 0x7f1a00043888 [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: Copying payload 9 (0x7f1a00046e78) from 0x7f19d1963bf0 to 0x7f1a00043888 [Apr 13 11:36:28] DEBUG[17071][C-00000001] rtp_engine.c: Copying payload 101 (0x7f1a0001e5f8) from 0x7f19d1963bf0 to 0x7f1a00043888 [Apr 13 11:36:28] DEBUG[17071][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f1a00043748' [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: We're settling with these formats: (ulaw|alaw) [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Checking SIP call limits for device ksy-test [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Updating call counter for incoming call [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: Splitting '192.168.0.177' into... [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: ...host '192.168.0.177' and port ''. [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: Splitting '192.168.0.177' into... [Apr 13 11:36:28] DEBUG[17071][C-00000001] netsock2.c: ...host '192.168.0.177' and port ''. [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw|alaw) [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: *** Our capabilities are (ulaw|alaw|ilbc|gsm|g726aal2) [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: This channel will not be able to handle video. [Apr 13 11:36:28] DEBUG[17021] threadpool.c: Increasing threadpool stasis-core's size by 1 [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: SIP/ksy-test-00000002: New call is still down.... Trying... [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.7.96:38790 [Apr 13 11:36:28] DEBUG[17033] devicestate.c: No provider found, checking channel drivers for SIP - ksy-test [Apr 13 11:36:28] DEBUG[17033] chan_sip.c: Checking device state for peer ksy-test [Apr 13 11:36:28] DEBUG[17033] devicestate.c: Changing state for SIP/ksy-test - state 1 (Not in use) [Apr 13 11:36:28] DEBUG[6253][C-00000001] pbx.c: Result of 'EXTEN' is '5000' [Apr 13 11:36:28] DEBUG[6253][C-00000001] pbx.c: Launching 'Dial' [Apr 13 11:36:28] VERBOSE[6253][C-00000001] pbx.c: Executing [5000@test-tcp:1] Dial("SIP/ksy-test-00000002", "SIP/asterisk-gw1/5000,90,rt") in new stack [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Asked to create a SIP channel with formats: (ulaw) [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Allocating new SIP dialog for 501a738e1729d5511a40342f095b9953@192.168.0.177:5060 - INVITE (No RTP) [Apr 13 11:36:28] DEBUG[6253][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f1a2c05f1f8' [Apr 13 11:36:28] DEBUG[6253][C-00000001] res_rtp_asterisk.c: Allocated port 12914 for RTP instance '0x7f1a2c05f1f8' [Apr 13 11:36:28] DEBUG[6253][C-00000001] netsock2.c: Splitting '192.168.0.172' into... [Apr 13 11:36:28] DEBUG[6253][C-00000001] netsock2.c: ...host '192.168.0.172' and port ''. [Apr 13 11:36:28] DEBUG[6253][C-00000001] netsock2.c: Splitting '192.168.0.177' into... [Apr 13 11:36:28] DEBUG[6253][C-00000001] netsock2.c: ...host '192.168.0.177' and port ''. [Apr 13 11:36:28] DEBUG[6253][C-00000001] rtp_engine.c: RTP instance '0x7f1a2c05f1f8' is setup and ready to go [Apr 13 11:36:28] DEBUG[6253][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f1a2c05f1f8' [Apr 13 11:36:28] VERBOSE[6253][C-00000001] netsock2.c: Using SIP RTP TOS bits 184 [Apr 13 11:36:28] VERBOSE[6253][C-00000001] netsock2.c: Using SIP RTP CoS mark 5 [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Setting NAT on RTP to On [Apr 13 11:36:28] DEBUG[6253][C-00000001] acl.c: For destination '192.168.0.30', our source address is '192.168.0.172'. [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Setting AST_TRANSPORT_TCP with address 192.168.0.177:5060 [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Setting NAT on RTP to On [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: SIP call-id changed from '501a738e1729d5511a40342f095b9953@192.168.0.177:5060' to '0d42bf501180073a7e3635ad202da6ac@192.168.0.177:5060' [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: *** Our capabilities are (ulaw|alaw) [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: This channel will not be able to handle video. [Apr 13 11:36:28] DEBUG[6253][C-00000001] channel_internal_api.c: Channel Call ID changing from [C-00000001] to [C-00000001] [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Outgoing Call for 5000 [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Updating call counter for outgoing call [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: ** Our capability: (ulaw|alaw) Video flag: False Text flag: False [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: ** Our prefcodec: (ulaw) [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw) [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid 0d42bf501180073a7e3635ad202da6ac@192.168.0.177:5060 [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Trying to put 'INVITE sip:' onto TCP socket destined for 192.168.0.30:5060 [Apr 13 11:36:28] VERBOSE[6253][C-00000001] app_dial.c: Called SIP/asterisk-gw1/5000 [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.7.96:38790 [Apr 13 11:36:28] DEBUG[6254] chan_sip.c: Starting thread for TCP server [Apr 13 11:36:28] DEBUG[6254] chan_sip.c: = Looking for Call ID: 0d42bf501180073a7e3635ad202da6ac@192.168.0.177:5060 (Checking To) --From tag as2c90d3ba --To-tag as28aecdbe [Apr 13 11:36:28] DEBUG[6254][C-00000001] chan_sip.c: SIP response 401 to standard invite [Apr 13 11:36:28] DEBUG[6254][C-00000001] chan_sip.c: Trying to put 'ACK sip:500' onto TCP socket destined for 192.168.0.30:5060 [Apr 13 11:36:28] DEBUG[6254][C-00000001] chan_sip.c: Auth attempt 1 on INVITE [Apr 13 11:36:28] DEBUG[6254][C-00000001] chan_sip.c: ** Our capability: (ulaw|alaw) Video flag: False Text flag: False [Apr 13 11:36:28] DEBUG[6254][C-00000001] chan_sip.c: ** Our prefcodec: (ulaw) [Apr 13 11:36:28] DEBUG[6254][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [Apr 13 11:36:28] DEBUG[6254][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw) [Apr 13 11:36:28] DEBUG[6254][C-00000001] chan_sip.c: Trying to put 'INVITE sip:' onto TCP socket destined for 192.168.0.30:5060 [Apr 13 11:36:28] DEBUG[6254] chan_sip.c: = Looking for Call ID: 0d42bf501180073a7e3635ad202da6ac@192.168.0.177:5060 (Checking To) --From tag as2c90d3ba --To-tag as28aecdbe [Apr 13 11:36:28] DEBUG[6254][C-00000001] chan_sip.c: SIP response 403 to standard invite [Apr 13 11:36:28] DEBUG[6254][C-00000001] chan_sip.c: Trying to put 'ACK sip:500' onto TCP socket destined for 192.168.0.30:5060 [Apr 13 11:36:28] WARNING[6254][C-00000001] chan_sip.c: Received response: "Forbidden" from '"Test" ;tag=as2c90d3ba' [Apr 13 11:36:28] DEBUG[6253][C-00000001] channel.c: Hanging up channel 'SIP/asterisk-gw1-00000003' [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Hangup call SIP/asterisk-gw1-00000003, SIP callid 0d42bf501180073a7e3635ad202da6ac@192.168.0.177:5060 [Apr 13 11:36:28] DEBUG[6253][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f1a2c05f1f8' [Apr 13 11:36:28] DEBUG[17034] cdr.c: Finalized CDR for SIP/ksy-test-00000002 - start 1492072588.691692 answer 0.000000 end 1492072588.740334 dispo NO ANSWER [Apr 13 11:36:28] DEBUG[17021] threadpool.c: Increasing threadpool stasis-core's size by 1 [Apr 13 11:36:28] DEBUG[17034] cdr.c: Finalized CDR for SIP/asterisk-gw1-00000003 - start 1492072588.693130 answer 0.000000 end 1492072588.740690 dispo NO ANSWER [Apr 13 11:36:28] DEBUG[17034] cdr.c: CDR for SIP/asterisk-gw1-00000003 is dialed and has no Party B; discarding [Apr 13 11:36:28] VERBOSE[6253][C-00000001] app_dial.c: Everyone is busy/congested at this time (1:0/0/1) [Apr 13 11:36:28] DEBUG[17033] devicestate.c: No provider found, checking channel drivers for SIP - asterisk-gw1 [Apr 13 11:36:28] DEBUG[17033] chan_sip.c: Checking device state for peer asterisk-gw1 [Apr 13 11:36:28] DEBUG[17033] devicestate.c: Changing state for SIP/asterisk-gw1 - state 1 (Not in use) [Apr 13 11:36:28] DEBUG[6253][C-00000001] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL. [Apr 13 11:36:28] DEBUG[6253][C-00000001] pbx.c: Launching 'Hangup' [Apr 13 11:36:28] VERBOSE[6253][C-00000001] pbx.c: Executing [5000@test-tcp:2] Hangup("SIP/ksy-test-00000002", "") in new stack [Apr 13 11:36:28] DEBUG[6253][C-00000001] channel.c: Soft-Hanging (0x20) up channel 'SIP/ksy-test-00000002' [Apr 13 11:36:28] DEBUG[6253][C-00000001] pbx.c: Spawn extension (test-tcp,5000,2) exited non-zero on 'SIP/ksy-test-00000002' [Apr 13 11:36:28] VERBOSE[6253][C-00000001] pbx.c: Spawn extension (test-tcp, 5000, 2) exited non-zero on 'SIP/ksy-test-00000002' [Apr 13 11:36:28] DEBUG[6253][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'SIP/ksy-test-00000002' [Apr 13 11:36:28] DEBUG[6253][C-00000001] channel.c: Hanging up channel 'SIP/ksy-test-00000002' [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Hangup call SIP/ksy-test-00000002, SIP callid d32edeab-0e61-496a-8218-ae48b028161c [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Hanging up channel in state Ring (not UP) [Apr 13 11:36:28] DEBUG[6253][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f1a00043748' [Apr 13 11:36:28] DEBUG[6253][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 403' onto UDP socket destined for 192.168.7.96:38790 [Apr 13 11:36:28] DEBUG[17034] cdr.c: Finalized CDR for SIP/ksy-test-00000002 - start 1492072588.740988 answer 0.000000 end 1492072588.741276 dispo NO ANSWER [Apr 13 11:36:28] DEBUG[17033] devicestate.c: No provider found, checking channel drivers for SIP - ksy-test [Apr 13 11:36:28] DEBUG[17033] chan_sip.c: Checking device state for peer ksy-test [Apr 13 11:36:28] DEBUG[17033] devicestate.c: Changing state for SIP/ksy-test - state 1 (Not in use) [Apr 13 11:36:28] DEBUG[17034] cdr_radius.c: Unable to create RADIUS record. CDR not recorded! [Apr 13 11:36:28] DEBUG[17034] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"Test" <5009>','5009','5000','test-tcp','SIP/ksy-test-00000002','SIP/asterisk-gw1-00000003','Dial','SIP/asterisk-gw1/5000,90,rt','2017-04-13 11:36:28','2017-04-13 11:36:28','0','0','NO ANSWER','DOCUMENTATION','minsk-sip-1492072588.3') [Apr 13 11:36:28] DEBUG[17071] chan_sip.c: = Looking for Call ID: d32edeab-0e61-496a-8218-ae48b028161c (Checking From) --From tag 5a9d10c2-0c90-4461-aafc-6831e8a21ebc --To-tag as457a89d2 [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Apr 13 11:36:28] DEBUG[17071][C-00000001] chan_sip.c: Stopping retransmission on 'd32edeab-0e61-496a-8218-ae48b028161c' of Response 19574: Match Found [Apr 13 11:36:28] DEBUG[17034] cdr.c: Skipping CDR for SIP/ksy-test-00000002 since we weren't answered [Apr 13 11:36:29] DEBUG[17071] chan_sip.c: Allocating new SIP dialog for 493ff2b5169e123a359ca572450f4e32@192.168.0.177:5060 - OPTIONS (No RTP) [Apr 13 11:36:29] DEBUG[17071] acl.c: For destination '192.168.0.30', our source address is '192.168.0.172'. [Apr 13 11:36:29] DEBUG[17071] chan_sip.c: Setting AST_TRANSPORT_TCP with address 192.168.0.177:5060 [Apr 13 11:36:29] DEBUG[17071] chan_sip.c: SIP call-id changed from '493ff2b5169e123a359ca572450f4e32@192.168.0.177:5060' to '12303f7b1c2b2c0d39dbfe380dcfbeda@192.168.0.177:5060' [Apr 13 11:36:29] DEBUG[17071] chan_sip.c: Initializing initreq for method OPTIONS - callid 12303f7b1c2b2c0d39dbfe380dcfbeda@192.168.0.177:5060 [Apr 13 11:36:29] DEBUG[17071] chan_sip.c: Trying to put 'OPTIONS sip' onto TCP socket destined for 192.168.0.30:5060 [Apr 13 11:36:29] DEBUG[6254] chan_sip.c: = Looking for Call ID: 12303f7b1c2b2c0d39dbfe380dcfbeda@192.168.0.177:5060 (Checking To) --From tag as043c20a7 --To-tag as6cd72616 [Apr 13 11:36:30] DEBUG[17071] chan_sip.c: Destroying SIP dialog 12303f7b1c2b2c0d39dbfe380dcfbeda@192.168.0.177:5060 [Apr 13 11:36:35] DEBUG[17071] chan_sip.c: Auto destroying SIP dialog '0d42bf501180073a7e3635ad202da6ac@192.168.0.177:5060' [Apr 13 11:36:35] DEBUG[17071] chan_sip.c: Destroying SIP dialog 0d42bf501180073a7e3635ad202da6ac@192.168.0.177:5060 [Apr 13 11:36:35] DEBUG[17071] rtp_engine.c: Destroyed RTP instance '0x7f1a2c05f1f8' [Apr 13 11:36:48] DEBUG[6255] threadpool.c: Worker thread idle timeout reached. Dying. [Apr 13 11:36:48] DEBUG[17021] threadpool.c: Destroying worker thread 30 [Apr 13 11:36:48] DEBUG[6252] threadpool.c: Worker thread idle timeout reached. Dying. [Apr 13 11:36:48] DEBUG[17021] threadpool.c: Destroying worker thread 29 [Apr 13 11:36:49] DEBUG[6300] chan_sip.c: Starting thread for TCP server [Apr 13 11:36:49] DEBUG[6300] chan_sip.c: = Looking for Call ID: 43fbdc1e183c0412229d9a084de552ab@192.168.0.30:5060 (Checking From) --From tag as7794af2b --To-tag [Apr 13 11:36:49] DEBUG[6300] acl.c: For destination '192.168.0.30', our source address is '192.168.0.172'. [Apr 13 11:36:49] DEBUG[6300] chan_sip.c: Setting AST_TRANSPORT_TCP with address 192.168.0.177:5060 [Apr 13 11:36:49] DEBUG[6300] netsock2.c: Splitting '192.168.0.30:5060' into... [Apr 13 11:36:49] DEBUG[6300] netsock2.c: ...host '192.168.0.30' and port '5060'. [Apr 13 11:36:49] DEBUG[6300] chan_sip.c: Allocating new SIP dialog for 43fbdc1e183c0412229d9a084de552ab@192.168.0.30:5060 - OPTIONS (No RTP) [Apr 13 11:36:49] DEBUG[6300] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Apr 13 11:36:49] DEBUG[6300] netsock2.c: Splitting '192.168.0.177' into... [Apr 13 11:36:49] DEBUG[6300] netsock2.c: ...host '192.168.0.177' and port ''. [Apr 13 11:36:49] DEBUG[6300] netsock2.c: Splitting '192.168.0.30' into... [Apr 13 11:36:49] DEBUG[6300] netsock2.c: ...host '192.168.0.30' and port ''. 11:36:28.693641 IP 192.168.0.172.46362 > 192.168.0.30.5060: Flags [S], seq 722237485, win 29200, options [mss 1460,sackOK,TS val 426772951 ecr 0,nop,wscale 7], length 0 11:36:28.695407 IP 192.168.0.30.5060 > 192.168.0.172.46362: Flags [S.], seq 544959177, ack 722237486, win 28960, options [mss 1460,sackOK,TS val 129779451 ecr 426772951,nop,wscale 7], length 0 11:36:28.695440 IP 192.168.0.172.46362 > 192.168.0.30.5060: Flags [.], ack 1, win 229, options [nop,nop,TS val 426772951 ecr 129779451], length 0 11:36:28.695515 IP 192.168.0.172.46362 > 192.168.0.30.5060: Flags [P.], seq 1:895, ack 1, win 229, options [nop,nop,TS val 426772951 ecr 129779451], length 894 .... [Apr 13 11:36:28] -- Executing [5000@test-tcp:1] Dial("SIP/ksy-test-00000002", "SIP/asterisk-gw1/5000,90,rt") in new stack [Apr 13 11:36:28] == Using SIP RTP TOS bits 184 [Apr 13 11:36:28] == Using SIP RTP CoS mark 5 [Apr 13 11:36:28] -- Called SIP/asterisk-gw1/5000 [Apr 13 11:36:28] WARNING[6254][C-00000001]: chan_sip.c:23225 handle_response_invite: Received response: "Forbidden" from '"Test" ;tag=as2c90d3ba' [Apr 13 11:36:28] == Everyone is busy/congested at this time (1:0/0/1) [Apr 13 11:36:28] -- Executing [5000@test-tcp:2] Hangup("SIP/ksy-test-00000002", "") in new stack [Apr 13 11:36:28] == Spawn extension (test-tcp, 5000, 2) exited non-zero on 'SIP/ksy-test-00000002'