[Jun 26 14:59:09] Asterisk 13.4.0-rc1 built by root @ test_pbx on a i686 running Linux on 2015-06-25 12:25:38 UTC [Jun 26 14:59:09] VERBOSE[28482] config.c: Parsing '/etc/asterisk/logger.conf': Found [Jun 26 14:59:09] VERBOSE[28482] logger.c: Asterisk Queue Logger restarted [Jun 26 14:59:32] DEBUG[28369] chan_sip.c: = Looking for Call ID: fa767460753445cb8b867d632ec23507 (Checking From) --From tag 2f63ca4de95e411baadf1e4e4a4644bc --To-tag [Jun 26 14:59:32] DEBUG[28369] acl.c: For destination 'ip_sip_caller', our source address is 'ip_pbx'. [Jun 26 14:59:32] DEBUG[28369] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:59:32] DEBUG[28369] netsock2.c: Splitting '192.168.1.5:52859' into... [Jun 26 14:59:32] DEBUG[28369] netsock2.c: ...host '192.168.1.5' and port '52859'. [Jun 26 14:59:32] DEBUG[28369] chan_sip.c: NAT detected for 192.168.1.5 / ip_sip_caller [Jun 26 14:59:32] DEBUG[28369] chan_sip.c: Allocating new SIP dialog for fa767460753445cb8b867d632ec23507 - INVITE (No RTP) [Jun 26 14:59:32] DEBUG[28369][C-00000005] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 26 14:59:32] DEBUG[28369][C-00000005] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [Jun 26 14:59:32] DEBUG[28369][C-00000005] sip/reqresp_parser.c: Found SIP option: -replaces- [Jun 26 14:59:32] DEBUG[28369][C-00000005] sip/reqresp_parser.c: Matched SIP option: replaces [Jun 26 14:59:32] DEBUG[28369][C-00000005] sip/reqresp_parser.c: Found SIP option: -100rel- [Jun 26 14:59:32] DEBUG[28369][C-00000005] sip/reqresp_parser.c: Matched SIP option: 100rel [Jun 26 14:59:32] DEBUG[28369][C-00000005] sip/reqresp_parser.c: Found SIP option: -timer- [Jun 26 14:59:32] DEBUG[28369][C-00000005] sip/reqresp_parser.c: Matched SIP option: timer [Jun 26 14:59:32] DEBUG[28369][C-00000005] sip/reqresp_parser.c: Found SIP option: -norefersub- [Jun 26 14:59:32] DEBUG[28369][C-00000005] sip/reqresp_parser.c: Matched SIP option: norefersub [Jun 26 14:59:32] DEBUG[28369][C-00000005] netsock2.c: Splitting '192.168.1.5:52859' into... [Jun 26 14:59:32] DEBUG[28369][C-00000005] netsock2.c: ...host '192.168.1.5' and port '52859'. [Jun 26 14:59:32] DEBUG[28369][C-00000005] chan_sip.c: NAT detected for 192.168.1.5 / ip_sip_caller [Jun 26 14:59:32] DEBUG[28369][C-00000005] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:59:32] DEBUG[28369][C-00000005] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:59:32] DEBUG[28369][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:59:32] DEBUG[28369] chan_sip.c: = Looking for Call ID: fa767460753445cb8b867d632ec23507 (Checking From) --From tag 2f63ca4de95e411baadf1e4e4a4644bc --To-tag as02955d38 [Jun 26 14:59:32] DEBUG[28369][C-00000005] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 26 14:59:32] DEBUG[28369][C-00000005] chan_sip.c: Stopping retransmission on 'fa767460753445cb8b867d632ec23507' of Response 2633: Match Found [Jun 26 14:59:33] DEBUG[28369] chan_sip.c: = Looking for Call ID: fa767460753445cb8b867d632ec23507 (Checking From) --From tag 2f63ca4de95e411baadf1e4e4a4644bc --To-tag [Jun 26 14:59:33] DEBUG[28369] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:59:33] DEBUG[28369] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:59:33] DEBUG[28369] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:59:33] DEBUG[28369] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: Splitting '192.168.1.5:52859' into... [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: ...host '192.168.1.5' and port '52859'. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: NAT detected for 192.168.1.5 / ip_sip_caller [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x8ee6f44' [Jun 26 14:59:33] DEBUG[28369][C-00000005] res_rtp_asterisk.c: Allocated port 17864 for RTP instance '0x8ee6f44' [Jun 26 14:59:33] DEBUG[28369][C-00000005] pjsip: icess0x8ee78dc ICE session created, comp_cnt=2, role is Unknown agent [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:59:33] DEBUG[28369][C-00000005] pjsip: icess0x8ee78dc Candidate 0 added: comp_id=1, type=host, foundation=Hd5a8a156, addr=ip_pbx:17864, base=ip_pbx:17864, prio=0x7effffff (2130706431) [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:59:33] DEBUG[28369][C-00000005] pjsip: icess0x8ee78dc Candidate 1 added: comp_id=1, type=srflx, foundation=Sd5a8a156, addr=ip_pbx:17864, base=ip_pbx:17864, prio=0x64ffffff (1694498815) [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: RTP instance '0x8ee6f44' is setup and ready to go [Jun 26 14:59:33] DEBUG[28369][C-00000005] pjsip: icess0x8ee78dc Destroying ICE session 0x8ee78dc [Jun 26 14:59:33] DEBUG[28369][C-00000005] pjsip: stuse0x8ee90d0 STUN session 0x8ee94ec destroy request, ref_cnt=4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] pjsip: stuse0x8ba2f18 STUN session 0x8ba3334 destroy request, ref_cnt=3 [Jun 26 14:59:33] DEBUG[28369][C-00000005] pjsip: ice_session.c ICE session 0x8ee78dc destroyed [Jun 26 14:59:33] DEBUG[28369][C-00000005] pjsip: stun_session.c STUN session 0x8ee94ec destroyed [Jun 26 14:59:33] DEBUG[28369][C-00000005] pjsip: stun_session.c STUN session 0x8ba3334 destroyed [Jun 26 14:59:33] DEBUG[28369][C-00000005] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x8ee6f44' [Jun 26 14:59:33] VERBOSE[28369][C-00000005] netsock2.c: Using SIP RTP CoS mark 5 [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Setting NAT on RTP to On [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing session-level SDP o=- 3644319572 3644319572 IN IP4 192.168.1.5... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing session-level SDP s=pjmedia... UNSUPPORTED OR FAILED. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing session-level SDP b=AS:84... UNSUPPORTED OR FAILED. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Setting payload 117 (0x8c8337c) based on m type on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Setting payload 107 (0x8c833c4) based on m type on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Setting payload 9 (0x8c8340c) based on m type on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Setting payload 8 (0x8c83454) based on m type on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Setting payload 0 (0x8c8349c) based on m type on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Setting payload 110 (0x8ee9b94) based on m type on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Setting payload 96 (0x8ee9bdc) based on m type on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Setting payload 97 (0x8ee9c24) based on m type on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Setting payload 3 (0x8ee9c6c) based on m type on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Setting payload 18 (0x8ba4014) based on m type on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Setting payload 101 (0x8ba405c) based on m type on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: Splitting '192.168.1.5' into... [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: ...host '192.168.1.5' and port ''. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 192.168.1.5... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP b=TIAS:64000... UNSUPPORTED OR FAILED. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4017 IN IP4 192.168.1.5... UNSUPPORTED OR FAILED. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:117 speex/16000... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Unsetting payload 107 on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:107 SILK/16000... UNSUPPORTED OR FAILED. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:110 speex/8000... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Unsetting payload 96 on 0xb44e3dc4 [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 SILK/8000... UNSUPPORTED OR FAILED. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 iLBC/8000... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=fmtp:97 mode=30... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Jun 26 14:59:33] DEBUG[28369][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8ee6f44' [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Copying payload 0 (0x8c8340c) from 0xb44e3dc4 to 0x8ee70f0 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Copying payload 3 (0x8ee9b94) from 0xb44e3dc4 to 0x8ee70f0 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Copying payload 8 (0x8c833c4) from 0xb44e3dc4 to 0x8ee70f0 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Copying payload 9 (0x8c8337c) from 0xb44e3dc4 to 0x8ee70f0 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Copying payload 18 (0x8ba40ec) from 0xb44e3dc4 to 0x8ee70f0 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Copying payload 97 (0x8c8349c) from 0xb44e3dc4 to 0x8ee70f0 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Copying payload 101 (0x8ba4014) from 0xb44e3dc4 to 0x8ee70f0 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Copying payload 110 (0x8c83454) from 0xb44e3dc4 to 0x8ee70f0 [Jun 26 14:59:33] DEBUG[28369][C-00000005] rtp_engine.c: Copying payload 117 (0x8ba40a4) from 0xb44e3dc4 to 0x8ee70f0 [Jun 26 14:59:33] DEBUG[28369][C-00000005] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x8ee6f44' [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: We're settling with these formats: (alaw) [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Checking SIP call limits for device vr1a885 [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Updating call counter for incoming call [Jun 26 14:59:33] DEBUG[28343] devicestate.c: No provider found, checking channel drivers for SIP - vr1a885 [Jun 26 14:59:33] DEBUG[28343] chan_sip.c: Checking device state for peer vr1a885 [Jun 26 14:59:33] DEBUG[28343] devicestate.c: Changing state for SIP/vr1a885 - state 2 (In use) [Jun 26 14:59:33] DEBUG[28406] app_queue.c: Device 'SIP/vr1a885' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:59:33] DEBUG[28369][C-00000005] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Incoming INVITE with 'timer' option supported [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: INVITE also has "Session-Expires" header. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Session-Expires: 1800 [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: INVITE also has "Min-SE" header. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Received Min-SE: 90 [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: *** Our native formats are (alaw) [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: *** Joint capabilities are (alaw) [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: *** Our capabilities are (alaw) [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: This channel will not be able to handle video. [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: SIP/vr1a885-00000002: New call is still down.... Trying... [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:59:33] DEBUG[28343] devicestate.c: No provider found, checking channel drivers for SIP - vr1a885 [Jun 26 14:59:33] DEBUG[28343] chan_sip.c: Checking device state for peer vr1a885 [Jun 26 14:59:33] DEBUG[28343] devicestate.c: Changing state for SIP/vr1a885 - state 2 (In use) [Jun 26 14:59:33] DEBUG[28484][C-00000005] pbx.c: Launching 'Dial' [Jun 26 14:59:33] VERBOSE[28484][C-00000005] pbx.c: Executing [884@from_phone:1] Dial("SIP/vr1a885-00000002", "SIP/vr1a884") in new stack [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: Asked to create a SIP channel with formats: (alaw) [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: Allocating new SIP dialog for 00a001095bb14e022ae70b7b5c4247d5@ip_pbx:5060 - INVITE (No RTP) [Jun 26 14:59:33] DEBUG[28484][C-00000005] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x8eec7bc' [Jun 26 14:59:33] DEBUG[28484][C-00000005] res_rtp_asterisk.c: Allocated port 19202 for RTP instance '0x8eec7bc' [Jun 26 14:59:33] DEBUG[28484][C-00000005] pjsip: icess0x8ee7504 ICE session created, comp_cnt=2, role is Unknown agent [Jun 26 14:59:33] DEBUG[28484][C-00000005] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:59:33] DEBUG[28484][C-00000005] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:59:33] DEBUG[28484][C-00000005] pjsip: icess0x8ee7504 Candidate 0 added: comp_id=1, type=host, foundation=Hd5a8a156, addr=ip_pbx:19202, base=ip_pbx:19202, prio=0x7effffff (2130706431) [Jun 26 14:59:33] DEBUG[28484][C-00000005] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:59:33] DEBUG[28484][C-00000005] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:59:33] DEBUG[28484][C-00000005] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:59:33] DEBUG[28484][C-00000005] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:59:33] DEBUG[28484][C-00000005] pjsip: icess0x8ee7504 Candidate 1 added: comp_id=1, type=srflx, foundation=Sd5a8a156, addr=ip_pbx:19202, base=ip_pbx:19202, prio=0x64ffffff (1694498815) [Jun 26 14:59:33] DEBUG[28484][C-00000005] rtp_engine.c: RTP instance '0x8eec7bc' is setup and ready to go [Jun 26 14:59:33] DEBUG[28484][C-00000005] pjsip: icess0x8ee7504 Destroying ICE session 0x8ee7504 [Jun 26 14:59:33] DEBUG[28484][C-00000005] pjsip: stuse0x8ee8f00 STUN session 0x8ee931c destroy request, ref_cnt=4 [Jun 26 14:59:33] DEBUG[28484][C-00000005] pjsip: stuse0x8ef1cf0 STUN session 0x8ef210c destroy request, ref_cnt=3 [Jun 26 14:59:33] DEBUG[28484][C-00000005] pjsip: ice_session.c ICE session 0x8ee7504 destroyed [Jun 26 14:59:33] DEBUG[28484][C-00000005] pjsip: stun_session.c STUN session 0x8ee931c destroyed [Jun 26 14:59:33] DEBUG[28484][C-00000005] pjsip: stun_session.c STUN session 0x8ef210c destroyed [Jun 26 14:59:33] DEBUG[28484][C-00000005] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x8eec7bc' [Jun 26 14:59:33] VERBOSE[28484][C-00000005] netsock2.c: Using SIP RTP CoS mark 5 [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: Setting NAT on RTP to On [Jun 26 14:59:33] DEBUG[28484][C-00000005] acl.c: For destination 'ip_sip_called', our source address is 'ip_pbx'. [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: Setting NAT on RTP to On [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: SIP call-id changed from '00a001095bb14e022ae70b7b5c4247d5@ip_pbx:5060' to '324f8df97421df3a582ec3f827548d17@ip_pbx:5060' [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: *** Our native formats are (alaw) [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: *** Joint capabilities are (alaw) [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: *** Our capabilities are (alaw) [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: *** Our preferred formats from the incoming channel are (alaw) [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: This channel will not be able to handle video. [Jun 26 14:59:33] DEBUG[28369] chan_sip.c: Auto destroying SIP dialog '2e8b3d889337ea50e3e42803153900bf' [Jun 26 14:59:33] DEBUG[28369] chan_sip.c: Destroying SIP dialog 2e8b3d889337ea50e3e42803153900bf [Jun 26 14:59:33] DEBUG[28484][C-00000005] channel_internal_api.c: Channel Call ID changing from [C-00000005] to [C-00000005] [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: Outgoing Call for vr1a884 [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: Updating call counter for outgoing call [Jun 26 14:59:33] DEBUG[28343] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:59:33] DEBUG[28343] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:59:33] DEBUG[28343] devicestate.c: Changing state for SIP/vr1a884 - state 6 (Ringing) [Jun 26 14:59:33] DEBUG[28406] app_queue.c: Device 'SIP/vr1a884' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: False [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: ** Our prefcodec: (alaw) [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: -- Done with adding codecs to SDP [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: Done building SDP. Settling with this capability: (alaw) [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: Initializing initreq for method INVITE - callid 324f8df97421df3a582ec3f827548d17@ip_pbx:5060 [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:59:33] VERBOSE[28484][C-00000005] app_dial.c: Called SIP/vr1a884 [Jun 26 14:59:33] DEBUG[28369] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #196)) [Jun 26 14:59:33] DEBUG[28369] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:59:33] DEBUG[28369] chan_sip.c: = Looking for Call ID: 324f8df97421df3a582ec3f827548d17@ip_pbx:5060 (Checking To) --From tag as1b5c2a6e --To-tag 2442531483 [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '324f8df97421df3a582ec3f827548d17@ip_pbx:5060' Request 102: Found [Jun 26 14:59:33] DEBUG[28369][C-00000005] chan_sip.c: SIP response 180 to standard invite [Jun 26 14:59:33] DEBUG[28343] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:59:33] DEBUG[28343] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:59:33] DEBUG[28343] devicestate.c: Changing state for SIP/vr1a884 - state 6 (Ringing) [Jun 26 14:59:33] VERBOSE[28484][C-00000005] app_dial.c: SIP/vr1a884-00000003 is ringing [Jun 26 14:59:33] DEBUG[28484][C-00000005] rtp_engine.c: Setting early bridge SDP of 'SIP/vr1a885-00000002' with that of 'SIP/vr1a884-00000003' [Jun 26 14:59:33] DEBUG[28484][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:59:37] DEBUG[28369] chan_sip.c: = Looking for Call ID: fa767460753445cb8b867d632ec23507 (Checking From) --From tag 2f63ca4de95e411baadf1e4e4a4644bc --To-tag [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL [Jun 26 14:59:37] DEBUG[28369][C-00000005] netsock2.c: Splitting '192.168.1.5:52859' into... [Jun 26 14:59:37] DEBUG[28369][C-00000005] netsock2.c: ...host '192.168.1.5' and port '52859'. [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: NAT detected for 192.168.1.5 / ip_sip_caller [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: Setting SIP_ALREADYGONE on dialog fa767460753445cb8b867d632ec23507 [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: Updating call counter for incoming call [Jun 26 14:59:37] DEBUG[28369][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8ee6f44' [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 487' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:59:37] DEBUG[28343] devicestate.c: No provider found, checking channel drivers for SIP - vr1a885 [Jun 26 14:59:37] DEBUG[28343] chan_sip.c: Checking device state for peer vr1a885 [Jun 26 14:59:37] DEBUG[28343] devicestate.c: Changing state for SIP/vr1a885 - state 1 (Not in use) [Jun 26 14:59:37] DEBUG[28484][C-00000005] channel.c: Hanging up channel 'SIP/vr1a884-00000003' [Jun 26 14:59:37] DEBUG[28484][C-00000005] chan_sip.c: Hangup call SIP/vr1a884-00000003, SIP callid 324f8df97421df3a582ec3f827548d17@ip_pbx:5060 [Jun 26 14:59:37] DEBUG[28484][C-00000005] chan_sip.c: Updating call counter for outgoing call [Jun 26 14:59:37] DEBUG[28484][C-00000005] chan_sip.c: Hanging up channel in state Ringing (not UP) [Jun 26 14:59:37] DEBUG[28484][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8eec7bc' [Jun 26 14:59:37] DEBUG[28484][C-00000005] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '324f8df97421df3a582ec3f827548d17@ip_pbx:5060' Request 102: Found [Jun 26 14:59:37] DEBUG[28484][C-00000005] chan_sip.c: Trying to put 'CANCEL sip:' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:59:37] DEBUG[28484][C-00000005] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Jun 26 14:59:37] DEBUG[28484][C-00000005] pbx.c: Spawn extension (from_phone,884,1) exited non-zero on 'SIP/vr1a885-00000002' [Jun 26 14:59:37] VERBOSE[28484][C-00000005] pbx.c: Spawn extension (from_phone, 884, 1) exited non-zero on 'SIP/vr1a885-00000002' [Jun 26 14:59:37] DEBUG[28484][C-00000005] channel.c: Soft-Hanging (0x10) up channel 'SIP/vr1a885-00000002' [Jun 26 14:59:37] DEBUG[28484][C-00000005] channel.c: Hanging up channel 'SIP/vr1a885-00000002' [Jun 26 14:59:37] DEBUG[28484][C-00000005] chan_sip.c: Hangup call SIP/vr1a885-00000002, SIP callid fa767460753445cb8b867d632ec23507 [Jun 26 14:59:37] DEBUG[28484][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8ee6f44' [Jun 26 14:59:37] DEBUG[28406] app_queue.c: Device 'SIP/vr1a885' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 26 14:59:37] DEBUG[28346] cdr.c: Finalized CDR for SIP/vr1a885-00000002 - start 1435323573.527144 answer 0.000000 end 1435323577.155792 dispo NO ANSWER [Jun 26 14:59:37] DEBUG[28346] cdr.c: Finalized CDR for SIP/vr1a884-00000003 - start 1435323573.556667 answer 0.000000 end 1435323577.155825 dispo NO ANSWER [Jun 26 14:59:37] DEBUG[28346] cdr.c: CDR for SIP/vr1a884-00000003 is dialed and has no Party B; discarding [Jun 26 14:59:37] DEBUG[28331] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jun 26 14:59:37] DEBUG[28343] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:59:37] DEBUG[28343] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:59:37] DEBUG[28343] devicestate.c: Changing state for SIP/vr1a884 - state 1 (Not in use) [Jun 26 14:59:37] DEBUG[28343] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:59:37] DEBUG[28343] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:59:37] DEBUG[28343] devicestate.c: Changing state for SIP/vr1a884 - state 1 (Not in use) [Jun 26 14:59:37] DEBUG[28343] devicestate.c: No provider found, checking channel drivers for SIP - vr1a885 [Jun 26 14:59:37] DEBUG[28343] chan_sip.c: Checking device state for peer vr1a885 [Jun 26 14:59:37] DEBUG[28343] devicestate.c: Changing state for SIP/vr1a885 - state 1 (Not in use) [Jun 26 14:59:37] DEBUG[28406] app_queue.c: Device 'SIP/vr1a884' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 26 14:59:37] DEBUG[28369] chan_sip.c: = Looking for Call ID: 324f8df97421df3a582ec3f827548d17@ip_pbx:5060 (Checking To) --From tag as1b5c2a6e --To-tag 2442531483 [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: Acked pending invite 102 [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: Stopping retransmission on '324f8df97421df3a582ec3f827548d17@ip_pbx:5060' of Request 102: Match Found [Jun 26 14:59:37] DEBUG[28369] chan_sip.c: = Looking for Call ID: 324f8df97421df3a582ec3f827548d17@ip_pbx:5060 (Checking To) --From tag as1b5c2a6e --To-tag 2442531483 [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: Stopping retransmission on '324f8df97421df3a582ec3f827548d17@ip_pbx:5060' of Request 102: Match Found [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: SIP response 487 to standard invite [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: Trying to put 'ACK sip:vr1' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: Updating call counter for outgoing call [Jun 26 14:59:37] DEBUG[28343] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:59:37] DEBUG[28343] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:59:37] DEBUG[28343] devicestate.c: Changing state for SIP/vr1a884 - state 1 (Not in use) [Jun 26 14:59:37] DEBUG[28369] chan_sip.c: = Looking for Call ID: fa767460753445cb8b867d632ec23507 (Checking From) --From tag 2f63ca4de95e411baadf1e4e4a4644bc --To-tag as140e54d3 [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 26 14:59:37] DEBUG[28369][C-00000005] chan_sip.c: Stopping retransmission on 'fa767460753445cb8b867d632ec23507' of Response 2634: Match Found [Jun 26 14:59:37] DEBUG[28369] chan_sip.c: Session timer stopped: -1 - fa767460753445cb8b867d632ec23507 [Jun 26 14:59:37] DEBUG[28369] chan_sip.c: Destroying SIP dialog fa767460753445cb8b867d632ec23507 [Jun 26 14:59:37] DEBUG[28369] rtp_engine.c: Destroyed RTP instance '0x8ee6f44' [Jun 26 14:59:39] DEBUG[28369] chan_sip.c: = Looking for Call ID: 527be73c090a130d2729bb9e444f4036@213.168.163.68:5060 (Checking From) --From tag as249f06e3 --To-tag [Jun 26 14:59:39] DEBUG[28369] acl.c: For destination '213.168.163.68', our source address is 'ip_pbx'. [Jun 26 14:59:39] DEBUG[28369] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:59:39] DEBUG[28369] netsock2.c: Splitting '213.168.163.68:5060' into... [Jun 26 14:59:39] DEBUG[28369] netsock2.c: ...host '213.168.163.68' and port '5060'. [Jun 26 14:59:39] DEBUG[28369] chan_sip.c: Allocating new SIP dialog for 527be73c090a130d2729bb9e444f4036@213.168.163.68:5060 - OPTIONS (No RTP) [Jun 26 14:59:39] DEBUG[28369] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jun 26 14:59:39] DEBUG[28369] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:59:39] DEBUG[28369] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:59:39] DEBUG[28369] netsock2.c: Splitting '213.168.163.68' into... [Jun 26 14:59:39] DEBUG[28369] netsock2.c: ...host '213.168.163.68' and port ''. [Jun 26 14:59:39] DEBUG[28369] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 213.168.163.68:5060 [Jun 26 14:59:40] VERBOSE[28482] asterisk.c: Remote UNIX connection disconnected [Jun 26 14:59:41] DEBUG[28369] chan_sip.c: Allocating new SIP dialog for 663dabc729ba9c7b3cd3e20d6506ebae@ip_pbx:5060 - OPTIONS (No RTP) [Jun 26 14:59:41] DEBUG[28369] acl.c: For destination 'ip_sip_caller', our source address is 'ip_pbx'. [Jun 26 14:59:41] DEBUG[28369] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:59:41] DEBUG[28369] chan_sip.c: SIP call-id changed from '663dabc729ba9c7b3cd3e20d6506ebae@ip_pbx:5060' to '1e7611bb7f85631d4453bdee1bd6363d@ip_pbx:5060' [Jun 26 14:59:41] DEBUG[28369] chan_sip.c: Initializing initreq for method OPTIONS - callid 1e7611bb7f85631d4453bdee1bd6363d@ip_pbx:5060 [Jun 26 14:59:41] DEBUG[28369] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:59:41] DEBUG[28369] chan_sip.c: = Looking for Call ID: 1e7611bb7f85631d4453bdee1bd6363d@ip_pbx:5060 (Checking To) --From tag as491a754e --To-tag z9hG4bK61accdee [Jun 26 14:59:41] DEBUG[28369] chan_sip.c: Stopping retransmission on '1e7611bb7f85631d4453bdee1bd6363d@ip_pbx:5060' of Request 102: Match Found [Jun 26 14:59:41] DEBUG[28369] chan_sip.c: Destroying SIP dialog 1e7611bb7f85631d4453bdee1bd6363d@ip_pbx:5060 [Jun 26 14:59:43] DEBUG[28369] chan_sip.c: Auto destroying SIP dialog '324f8df97421df3a582ec3f827548d17@ip_pbx:5060' [Jun 26 14:59:43] DEBUG[28369] chan_sip.c: Destroying SIP dialog 324f8df97421df3a582ec3f827548d17@ip_pbx:5060 [Jun 26 14:59:43] DEBUG[28369] rtp_engine.c: Destroyed RTP instance '0x8eec7bc' [Jun 26 14:59:49] DEBUG[28369] chan_sip.c: Auto destroying SIP dialog '2aedf99204f7a274' [Jun 26 14:59:49] DEBUG[28369] chan_sip.c: Destroying SIP dialog 2aedf99204f7a274 [Jun 26 14:59:57] DEBUG[28483] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 26 14:59:57] DEBUG[28331] threadpool.c: Destroying worker thread 24 [Jun 26 14:59:57] DEBUG[28485] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 26 14:59:57] DEBUG[28331] threadpool.c: Destroying worker thread 25 [Jun 26 15:00:02] DEBUG[28369] chan_sip.c: = Looking for Call ID: 2aedf99204f7a274 (Checking From) --From tag ea2141f90a --To-tag [Jun 26 15:00:02] DEBUG[28369] acl.c: For destination 'ip_sip_called', our source address is 'ip_pbx'. [Jun 26 15:00:02] DEBUG[28369] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 15:00:02] DEBUG[28369] netsock2.c: Splitting 'ip_sip_called:5060' into... [Jun 26 15:00:02] DEBUG[28369] netsock2.c: ...host 'ip_sip_called' and port '5060'. [Jun 26 15:00:02] DEBUG[28369] chan_sip.c: Allocating new SIP dialog for 2aedf99204f7a274 - REGISTER (No RTP) [Jun 26 15:00:02] DEBUG[28369] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 26 15:00:02] DEBUG[28369] netsock2.c: Splitting 'ip_sip_called:5060' into... [Jun 26 15:00:02] DEBUG[28369] netsock2.c: ...host 'ip_sip_called' and port '5060'. [Jun 26 15:00:02] DEBUG[28369] netsock2.c: Splitting 'test_pbx:5060' into... [Jun 26 15:00:02] DEBUG[28369] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 15:00:02] DEBUG[28369] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for ip_sip_called:5060 [Jun 26 15:00:02] DEBUG[28369] chan_sip.c: = Looking for Call ID: 2aedf99204f7a274 (Checking From) --From tag ea2141f90a --To-tag [Jun 26 15:00:02] DEBUG[28369] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 26 15:00:02] DEBUG[28369] netsock2.c: Splitting 'ip_sip_called:5060' into... [Jun 26 15:00:02] DEBUG[28369] netsock2.c: ...host 'ip_sip_called' and port '5060'. [Jun 26 15:00:02] DEBUG[28369] netsock2.c: Splitting 'test_pbx:5060' into... [Jun 26 15:00:02] DEBUG[28369] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 15:00:02] DEBUG[28369] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Jun 26 15:00:02] DEBUG[28369] chan_sip.c: build_path: do not use Path headers