[Jun 26 14:45:41] DEBUG[18445] chan_sip.c: Destroying SIP dialog 4362608f45cb92bd4a11a292198619fb@ip_pbx:5060 [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: = Looking for Call ID: 2aedf99204f7a274 (Checking From) --From tag ea2141f90a --To-tag [Jun 26 14:45:44] DEBUG[18445] acl.c: For destination 'ip_sip_called', our source address is 'ip_pbx'. [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:45:44] DEBUG[18445] netsock2.c: Splitting 'ip_sip_called:5060' into... [Jun 26 14:45:44] DEBUG[18445] netsock2.c: ...host 'ip_sip_called' and port '5060'. [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: Allocating new SIP dialog for 2aedf99204f7a274 - REGISTER (No RTP) [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 26 14:45:44] DEBUG[18445] netsock2.c: Splitting 'ip_sip_called:5060' into... [Jun 26 14:45:44] DEBUG[18445] netsock2.c: ...host 'ip_sip_called' and port '5060'. [Jun 26 14:45:44] DEBUG[18445] netsock2.c: Splitting 'test_pbx:5060' into... [Jun 26 14:45:44] DEBUG[18445] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: = Looking for Call ID: 2aedf99204f7a274 (Checking From) --From tag ea2141f90a --To-tag [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 26 14:45:44] DEBUG[18445] netsock2.c: Splitting 'ip_sip_called:5060' into... [Jun 26 14:45:44] DEBUG[18445] netsock2.c: ...host 'ip_sip_called' and port '5060'. [Jun 26 14:45:44] DEBUG[18445] netsock2.c: Splitting 'test_pbx:5060' into... [Jun 26 14:45:44] DEBUG[18445] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: build_path: do not use Path headers [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: Allocating new SIP dialog for 7271fbbf1006f8cf2b6cab4555ec67ee@ip_pbx:5060 - OPTIONS (No RTP) [Jun 26 14:45:44] DEBUG[18445] acl.c: For destination 'ip_sip_called', our source address is 'ip_pbx'. [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: SIP call-id changed from '7271fbbf1006f8cf2b6cab4555ec67ee@ip_pbx:5060' to '68f8ad26515b997c1cb2de2c3a43248d@ip_pbx:5060' [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: Initializing initreq for method OPTIONS - callid 68f8ad26515b997c1cb2de2c3a43248d@ip_pbx:5060 [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:45:44] DEBUG[18408] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jun 26 14:45:44] DEBUG[18420] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:45:44] DEBUG[18420] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:45:44] DEBUG[18420] devicestate.c: Changing state for SIP/vr1a884 - state 1 (Not in use) [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: = Looking for Call ID: 68f8ad26515b997c1cb2de2c3a43248d@ip_pbx:5060 (Checking To) --From tag as0aee5df5 --To-tag 3474164624 [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: Stopping retransmission on '68f8ad26515b997c1cb2de2c3a43248d@ip_pbx:5060' of Request 102: Match Found [Jun 26 14:45:44] DEBUG[18445] chan_sip.c: Destroying SIP dialog 68f8ad26515b997c1cb2de2c3a43248d@ip_pbx:5060 [Jun 26 14:45:55] DEBUG[18445] chan_sip.c: Allocating new SIP dialog for 61e058be43e9893d5e93957d279fded7@ip_pbx:5060 - OPTIONS (No RTP) [Jun 26 14:45:55] DEBUG[18445] acl.c: For destination 'ip_sip_caller', our source address is 'ip_pbx'. [Jun 26 14:45:55] DEBUG[18445] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:45:55] DEBUG[18445] chan_sip.c: SIP call-id changed from '61e058be43e9893d5e93957d279fded7@ip_pbx:5060' to '63486f53259a4f011453aeb313ee657c@ip_pbx:5060' [Jun 26 14:45:55] DEBUG[18445] chan_sip.c: Initializing initreq for method OPTIONS - callid 63486f53259a4f011453aeb313ee657c@ip_pbx:5060 [Jun 26 14:45:55] DEBUG[18445] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:45:55] DEBUG[18445] chan_sip.c: = Looking for Call ID: 63486f53259a4f011453aeb313ee657c@ip_pbx:5060 (Checking To) --From tag as053da7f3 --To-tag z9hG4bK742a71a0 [Jun 26 14:45:55] DEBUG[18445] chan_sip.c: Stopping retransmission on '63486f53259a4f011453aeb313ee657c@ip_pbx:5060' of Request 102: Match Found [Jun 26 14:45:55] DEBUG[18445] chan_sip.c: Destroying SIP dialog 63486f53259a4f011453aeb313ee657c@ip_pbx:5060 [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: = Looking for Call ID: 4f95e217710a42279ebc3b52d4d2a34a (Checking From) --From tag b1346184fe4343b7a0027ce8f0ee0663 --To-tag [Jun 26 14:46:04] DEBUG[18445] acl.c: For destination 'ip_sip_caller', our source address is 'ip_pbx'. [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:46:04] DEBUG[18445] netsock2.c: Splitting '192.168.1.5:52859' into... [Jun 26 14:46:04] DEBUG[18445] netsock2.c: ...host '192.168.1.5' and port '52859'. [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: NAT detected for 192.168.1.5 / ip_sip_caller [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: Allocating new SIP dialog for 4f95e217710a42279ebc3b52d4d2a34a - INVITE (No RTP) [Jun 26 14:46:04] DEBUG[18445][C-00000003] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 26 14:46:04] DEBUG[18445][C-00000003] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [Jun 26 14:46:04] DEBUG[18445][C-00000003] sip/reqresp_parser.c: Found SIP option: -replaces- [Jun 26 14:46:04] DEBUG[18445][C-00000003] sip/reqresp_parser.c: Matched SIP option: replaces [Jun 26 14:46:04] DEBUG[18445][C-00000003] sip/reqresp_parser.c: Found SIP option: -100rel- [Jun 26 14:46:04] DEBUG[18445][C-00000003] sip/reqresp_parser.c: Matched SIP option: 100rel [Jun 26 14:46:04] DEBUG[18445][C-00000003] sip/reqresp_parser.c: Found SIP option: -timer- [Jun 26 14:46:04] DEBUG[18445][C-00000003] sip/reqresp_parser.c: Matched SIP option: timer [Jun 26 14:46:04] DEBUG[18445][C-00000003] sip/reqresp_parser.c: Found SIP option: -norefersub- [Jun 26 14:46:04] DEBUG[18445][C-00000003] sip/reqresp_parser.c: Matched SIP option: norefersub [Jun 26 14:46:04] DEBUG[18445][C-00000003] netsock2.c: Splitting '192.168.1.5:52859' into... [Jun 26 14:46:04] DEBUG[18445][C-00000003] netsock2.c: ...host '192.168.1.5' and port '52859'. [Jun 26 14:46:04] DEBUG[18445][C-00000003] chan_sip.c: NAT detected for 192.168.1.5 / ip_sip_caller [Jun 26 14:46:04] DEBUG[18445][C-00000003] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:46:04] DEBUG[18445][C-00000003] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:46:04] DEBUG[18445][C-00000003] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:46:04] DEBUG[18505] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 26 14:46:04] DEBUG[18408] threadpool.c: Destroying worker thread 15 [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 228 ms (t1 114 ms (Retrans id #95)) [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: = Looking for Call ID: 4f95e217710a42279ebc3b52d4d2a34a (Checking From) --From tag b1346184fe4343b7a0027ce8f0ee0663 --To-tag as46f0b975 [Jun 26 14:46:04] DEBUG[18445][C-00000003] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 26 14:46:04] DEBUG[18445][C-00000003] chan_sip.c: Stopping retransmission on '4f95e217710a42279ebc3b52d4d2a34a' of Response 605: Match Found [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: = Looking for Call ID: 4f95e217710a42279ebc3b52d4d2a34a (Checking From) --From tag b1346184fe4343b7a0027ce8f0ee0663 --To-tag as46f0b975 [Jun 26 14:46:04] DEBUG[18445][C-00000003] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: = Looking for Call ID: d73a1f1e126c9cbddcca88d33fb0e2ef (Checking From) --From tag 0c26cd11 --To-tag [Jun 26 14:46:04] DEBUG[18445] acl.c: For destination '88.150.250.50', our source address is 'ip_pbx'. [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:46:04] DEBUG[18445] netsock2.c: Splitting 'ip_pbx:37811' into... [Jun 26 14:46:04] DEBUG[18445] netsock2.c: ...host 'ip_pbx' and port '37811'. [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: NAT detected for ip_pbx / 88.150.250.50 [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: Allocating new SIP dialog for d73a1f1e126c9cbddcca88d33fb0e2ef - REGISTER (No RTP) [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 26 14:46:04] DEBUG[18445] netsock2.c: Splitting 'ip_pbx:37811' into... [Jun 26 14:46:04] DEBUG[18445] netsock2.c: ...host 'ip_pbx' and port '37811'. [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: NAT detected for ip_pbx / 88.150.250.50 [Jun 26 14:46:04] DEBUG[18445] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:46:04] DEBUG[18445] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:46:04] DEBUG[18445] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 88.150.250.50:37811 [Jun 26 14:46:05] DEBUG[18445] chan_sip.c: = Looking for Call ID: 4f95e217710a42279ebc3b52d4d2a34a (Checking From) --From tag b1346184fe4343b7a0027ce8f0ee0663 --To-tag [Jun 26 14:46:05] DEBUG[18445] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:46:05] DEBUG[18445] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:46:05] DEBUG[18445] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:46:05] DEBUG[18445] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: Splitting '192.168.1.5:52859' into... [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: ...host '192.168.1.5' and port '52859'. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: NAT detected for 192.168.1.5 / ip_sip_caller [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb6c1976c' [Jun 26 14:46:05] DEBUG[18445][C-00000003] res_rtp_asterisk.c: Allocated port 17304 for RTP instance '0xb6c1976c' [Jun 26 14:46:05] DEBUG[18445][C-00000003] pjsip: icess0xb6c161a ICE session created, comp_cnt=2, role is Unknown agent [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:46:05] DEBUG[18445][C-00000003] pjsip: icess0xb6c161a Candidate 0 added: comp_id=1, type=host, foundation=Hd5a8a156, addr=ip_pbx:17304, base=ip_pbx:17304, prio=0x7effffff (2130706431) [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:46:05] DEBUG[18445][C-00000003] pjsip: icess0xb6c161a Candidate 1 added: comp_id=1, type=srflx, foundation=Sd5a8a156, addr=ip_pbx:17304, base=ip_pbx:17304, prio=0x64ffffff (1694498815) [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: RTP instance '0xb6c1976c' is setup and ready to go [Jun 26 14:46:05] DEBUG[18445][C-00000003] pjsip: icess0xb6c161a Destroying ICE session 0xb6c161ac [Jun 26 14:46:05] DEBUG[18445][C-00000003] pjsip: stuse0xb6c179a STUN session 0xb6c11544 destroy request, ref_cnt=4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] pjsip: stuse0xb6c1211 STUN session 0xb6c1252c destroy request, ref_cnt=3 [Jun 26 14:46:05] DEBUG[18445][C-00000003] pjsip: ice_session.c ICE session 0xb6c161ac destroyed [Jun 26 14:46:05] DEBUG[18445][C-00000003] pjsip: stun_session.c STUN session 0xb6c11544 destroyed [Jun 26 14:46:05] DEBUG[18445][C-00000003] pjsip: stun_session.c STUN session 0xb6c1252c destroyed [Jun 26 14:46:05] DEBUG[18445][C-00000003] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb6c1976c' [Jun 26 14:46:05] VERBOSE[18445][C-00000003] netsock2.c: Using SIP RTP CoS mark 5 [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Setting NAT on RTP to On [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing session-level SDP o=- 3644318764 3644318764 IN IP4 192.168.1.5... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing session-level SDP s=pjmedia... UNSUPPORTED OR FAILED. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing session-level SDP b=AS:84... UNSUPPORTED OR FAILED. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Setting payload 117 (0xb6c066dc) based on m type on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Setting payload 107 (0xb6c19e1c) based on m type on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Setting payload 9 (0xb6c19e64) based on m type on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Setting payload 8 (0xb6c19eac) based on m type on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Setting payload 0 (0xb6c19ef4) based on m type on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Setting payload 110 (0xb6c19f3c) based on m type on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Setting payload 96 (0xb6c0add4) based on m type on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Setting payload 97 (0xb6c0ae1c) based on m type on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Setting payload 3 (0xb6c0ae64) based on m type on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Setting payload 18 (0xb6c0aeac) based on m type on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Setting payload 101 (0xb6c0aef4) based on m type on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: Splitting '192.168.1.5' into... [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: ...host '192.168.1.5' and port ''. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 192.168.1.5... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP b=TIAS:64000... UNSUPPORTED OR FAILED. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4013 IN IP4 192.168.1.5... UNSUPPORTED OR FAILED. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:117 speex/16000... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Unsetting payload 107 on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:107 SILK/16000... UNSUPPORTED OR FAILED. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:110 speex/8000... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Unsetting payload 96 on 0xb4483dc4 [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 SILK/8000... UNSUPPORTED OR FAILED. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 iLBC/8000... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=fmtp:97 mode=30... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Jun 26 14:46:05] DEBUG[18445][C-00000003] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6c1976c' [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Copying payload 0 (0xb6c19eac) from 0xb4483dc4 to 0xb6c19918 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Copying payload 3 (0xb6c0ae1c) from 0xb4483dc4 to 0xb6c19918 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Copying payload 8 (0xb6c19e64) from 0xb4483dc4 to 0xb6c19918 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Copying payload 9 (0xb6c19e1c) from 0xb4483dc4 to 0xb6c19918 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Copying payload 18 (0xb6c0ae64) from 0xb4483dc4 to 0xb6c19918 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Copying payload 97 (0xb6c0add4) from 0xb4483dc4 to 0xb6c19918 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Copying payload 101 (0xb6c0aeac) from 0xb4483dc4 to 0xb6c19918 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Copying payload 110 (0xb6c19ef4) from 0xb4483dc4 to 0xb6c19918 [Jun 26 14:46:05] DEBUG[18445][C-00000003] rtp_engine.c: Copying payload 117 (0xb6c14f0c) from 0xb4483dc4 to 0xb6c19918 [Jun 26 14:46:05] DEBUG[18445][C-00000003] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb6c1976c' [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: We're settling with these formats: (alaw) [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Checking SIP call limits for device vr1a885 [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Updating call counter for incoming call [Jun 26 14:46:05] DEBUG[18420] devicestate.c: No provider found, checking channel drivers for SIP - vr1a885 [Jun 26 14:46:05] DEBUG[18420] chan_sip.c: Checking device state for peer vr1a885 [Jun 26 14:46:05] DEBUG[18420] devicestate.c: Changing state for SIP/vr1a885 - state 2 (In use) [Jun 26 14:46:05] DEBUG[18424] devicestate.c: No provider found, checking channel drivers for sip - vr1a885 [Jun 26 14:46:05] DEBUG[18424] chan_sip.c: Checking device state for peer vr1a885 [Jun 26 14:46:05] DEBUG[18424] devicestate.c: Checking if I can find provider for "Custom" - number: agent_2 [Jun 26 14:46:05] DEBUG[18424] devicestate.c: Checking provider Custom with Custom [Jun 26 14:46:05] DEBUG[18424] db.c: Unable to find key 'agent_2' in family 'CustomDevstate' [Jun 26 14:46:05] DEBUG[18424] app_queue.c: Extension '885@subscribe_1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 26 14:46:05] DEBUG[18480] 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:46:05] DEBUG[18445][C-00000003] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: Splitting 'test_pbx' into... [Jun 26 14:46:05] DEBUG[18445][C-00000003] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Incoming INVITE with 'timer' option supported [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: INVITE also has "Session-Expires" header. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Session-Expires: 1800 [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: INVITE also has "Min-SE" header. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Received Min-SE: 90 [Jun 26 14:46:05] DEBUG[18408] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: *** Our native formats are (alaw) [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: *** Joint capabilities are (alaw) [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: *** Our capabilities are (alaw) [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: This channel will not be able to handle video. [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: SIP/vr1a885-00000002: New call is still down.... Trying... [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:46:05] DEBUG[18420] devicestate.c: No provider found, checking channel drivers for SIP - vr1a885 [Jun 26 14:46:05] DEBUG[18420] chan_sip.c: Checking device state for peer vr1a885 [Jun 26 14:46:05] DEBUG[18420] devicestate.c: Changing state for SIP/vr1a885 - state 2 (In use) [Jun 26 14:46:05] DEBUG[18507][C-00000003] pbx.c: Launching 'Dial' [Jun 26 14:46:05] VERBOSE[18507][C-00000003] pbx.c: Executing [884@from_phone:1] Dial("SIP/vr1a885-00000002", "SIP/vr1a884") in new stack [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: Asked to create a SIP channel with formats: (alaw) [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: Allocating new SIP dialog for 267a12622915d37628ffafa9691cf95e@ip_pbx:5060 - INVITE (No RTP) [Jun 26 14:46:05] DEBUG[18507][C-00000003] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x991fe7c' [Jun 26 14:46:05] DEBUG[18507][C-00000003] res_rtp_asterisk.c: Allocated port 13712 for RTP instance '0x991fe7c' [Jun 26 14:46:05] DEBUG[18507][C-00000003] pjsip: icess0x9924094 ICE session created, comp_cnt=2, role is Unknown agent [Jun 26 14:46:05] DEBUG[18507][C-00000003] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:46:05] DEBUG[18507][C-00000003] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:46:05] DEBUG[18507][C-00000003] pjsip: icess0x9924094 Candidate 0 added: comp_id=1, type=host, foundation=Hd5a8a156, addr=ip_pbx:13712, base=ip_pbx:13712, prio=0x7effffff (2130706431) [Jun 26 14:46:05] DEBUG[18507][C-00000003] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:46:05] DEBUG[18507][C-00000003] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:46:05] DEBUG[18507][C-00000003] netsock2.c: Splitting 'ip_pbx' into... [Jun 26 14:46:05] DEBUG[18507][C-00000003] netsock2.c: ...host 'ip_pbx' and port ''. [Jun 26 14:46:05] DEBUG[18507][C-00000003] pjsip: icess0x9924094 Candidate 1 added: comp_id=1, type=srflx, foundation=Sd5a8a156, addr=ip_pbx:13712, base=ip_pbx:13712, prio=0x64ffffff (1694498815) [Jun 26 14:46:05] DEBUG[18507][C-00000003] rtp_engine.c: RTP instance '0x991fe7c' is setup and ready to go [Jun 26 14:46:05] DEBUG[18507][C-00000003] pjsip: icess0x9924094 Destroying ICE session 0x9924094 [Jun 26 14:46:05] DEBUG[18507][C-00000003] pjsip: stuse0x9922f80 STUN session 0x992339c destroy request, ref_cnt=4 [Jun 26 14:46:05] DEBUG[18507][C-00000003] pjsip: stuse0x9925c90 STUN session 0x99260ac destroy request, ref_cnt=3 [Jun 26 14:46:05] DEBUG[18507][C-00000003] pjsip: ice_session.c ICE session 0x9924094 destroyed [Jun 26 14:46:05] DEBUG[18507][C-00000003] pjsip: stun_session.c STUN session 0x992339c destroyed [Jun 26 14:46:05] DEBUG[18507][C-00000003] pjsip: stun_session.c STUN session 0x99260ac destroyed [Jun 26 14:46:05] DEBUG[18507][C-00000003] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x991fe7c' [Jun 26 14:46:05] VERBOSE[18507][C-00000003] netsock2.c: Using SIP RTP CoS mark 5 [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: Setting NAT on RTP to On [Jun 26 14:46:05] DEBUG[18507][C-00000003] acl.c: For destination 'ip_sip_called', our source address is 'ip_pbx'. [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: Setting NAT on RTP to On [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: SIP call-id changed from '267a12622915d37628ffafa9691cf95e@ip_pbx:5060' to '1289a4917def18c5479ac9782231a6c0@ip_pbx:5060' [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: *** Our native formats are (alaw) [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: *** Joint capabilities are (alaw) [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: *** Our capabilities are (alaw) [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: *** Our preferred formats from the incoming channel are (alaw) [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: This channel will not be able to handle video. [Jun 26 14:46:05] DEBUG[18507][C-00000003] channel_internal_api.c: Channel Call ID changing from [C-00000003] to [C-00000003] [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: Outgoing Call for vr1a884 [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: Updating call counter for outgoing call [Jun 26 14:46:05] DEBUG[18420] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:46:05] DEBUG[18420] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:46:05] DEBUG[18420] devicestate.c: Changing state for SIP/vr1a884 - state 6 (Ringing) [Jun 26 14:46:05] DEBUG[18424] devicestate.c: No provider found, checking channel drivers for sip - vr1a884 [Jun 26 14:46:05] DEBUG[18424] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:46:05] DEBUG[18424] devicestate.c: Checking if I can find provider for "Custom" - number: agent_1 [Jun 26 14:46:05] DEBUG[18424] devicestate.c: Checking provider Custom with Custom [Jun 26 14:46:05] DEBUG[18424] db.c: Unable to find key 'agent_1' in family 'CustomDevstate' [Jun 26 14:46:05] DEBUG[18424] app_queue.c: Extension '884@subscribe_1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 26 14:46:05] DEBUG[18480] 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:46:05] DEBUG[18507][C-00000003] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: False [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: ** Our prefcodec: (alaw) [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: -- Done with adding codecs to SDP [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: Done building SDP. Settling with this capability: (alaw) [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: Initializing initreq for method INVITE - callid 1289a4917def18c5479ac9782231a6c0@ip_pbx:5060 [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:46:05] VERBOSE[18507][C-00000003] app_dial.c: Called SIP/vr1a884 [Jun 26 14:46:05] DEBUG[18445] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #99)) [Jun 26 14:46:05] DEBUG[18445] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:46:05] DEBUG[18445] chan_sip.c: = Looking for Call ID: 1289a4917def18c5479ac9782231a6c0@ip_pbx:5060 (Checking To) --From tag as455adfae --To-tag 3100233905 [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1289a4917def18c5479ac9782231a6c0@ip_pbx:5060' Request 102: Found [Jun 26 14:46:05] DEBUG[18445][C-00000003] chan_sip.c: SIP response 180 to standard invite [Jun 26 14:46:05] DEBUG[18420] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:46:05] DEBUG[18420] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:46:05] DEBUG[18420] devicestate.c: Changing state for SIP/vr1a884 - state 6 (Ringing) [Jun 26 14:46:05] VERBOSE[18507][C-00000003] app_dial.c: SIP/vr1a884-00000003 is ringing [Jun 26 14:46:05] DEBUG[18507][C-00000003] rtp_engine.c: Setting early bridge SDP of 'SIP/vr1a885-00000002' with that of 'SIP/vr1a884-00000003' [Jun 26 14:46:05] DEBUG[18507][C-00000003] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:46:11] DEBUG[18445] chan_sip.c: Auto destroying SIP dialog '3b21161070f18714186dff920e4a567a@213.168.163.68:5060' [Jun 26 14:46:11] DEBUG[18445] chan_sip.c: Destroying SIP dialog 3b21161070f18714186dff920e4a567a@213.168.163.68:5060 [Jun 26 14:46:14] DEBUG[18445] chan_sip.c: = Looking for Call ID: 4f95e217710a42279ebc3b52d4d2a34a (Checking From) --From tag b1346184fe4343b7a0027ce8f0ee0663 --To-tag [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL [Jun 26 14:46:14] DEBUG[18445][C-00000003] netsock2.c: Splitting '192.168.1.5:52859' into... [Jun 26 14:46:14] DEBUG[18445][C-00000003] netsock2.c: ...host '192.168.1.5' and port '52859'. [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: NAT detected for 192.168.1.5 / ip_sip_caller [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: Setting SIP_ALREADYGONE on dialog 4f95e217710a42279ebc3b52d4d2a34a [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: Updating call counter for incoming call [Jun 26 14:46:14] DEBUG[18445][C-00000003] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6c1976c' [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: Trying to put 'SIP/2.0 487' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for ip_sip_caller:52859 [Jun 26 14:46:14] DEBUG[18420] devicestate.c: No provider found, checking channel drivers for SIP - vr1a885 [Jun 26 14:46:14] DEBUG[18420] chan_sip.c: Checking device state for peer vr1a885 [Jun 26 14:46:14] DEBUG[18420] devicestate.c: Changing state for SIP/vr1a885 - state 1 (Not in use) [Jun 26 14:46:14] DEBUG[18507][C-00000003] channel.c: Hanging up channel 'SIP/vr1a884-00000003' [Jun 26 14:46:14] DEBUG[18507][C-00000003] chan_sip.c: Hangup call SIP/vr1a884-00000003, SIP callid 1289a4917def18c5479ac9782231a6c0@ip_pbx:5060 [Jun 26 14:46:14] DEBUG[18507][C-00000003] chan_sip.c: Updating call counter for outgoing call [Jun 26 14:46:14] DEBUG[18507][C-00000003] chan_sip.c: Hanging up channel in state Ringing (not UP) [Jun 26 14:46:14] DEBUG[18507][C-00000003] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x991fe7c' [Jun 26 14:46:14] DEBUG[18507][C-00000003] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1289a4917def18c5479ac9782231a6c0@ip_pbx:5060' Request 102: Found [Jun 26 14:46:14] DEBUG[18507][C-00000003] chan_sip.c: Trying to put 'CANCEL sip:' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:46:14] DEBUG[18507][C-00000003] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Jun 26 14:46:14] DEBUG[18507][C-00000003] pbx.c: Spawn extension (from_phone,884,1) exited non-zero on 'SIP/vr1a885-00000002' [Jun 26 14:46:14] VERBOSE[18507][C-00000003] pbx.c: Spawn extension (from_phone, 884, 1) exited non-zero on 'SIP/vr1a885-00000002' [Jun 26 14:46:14] DEBUG[18507][C-00000003] channel.c: Soft-Hanging (0x10) up channel 'SIP/vr1a885-00000002' [Jun 26 14:46:14] DEBUG[18507][C-00000003] channel.c: Hanging up channel 'SIP/vr1a885-00000002' [Jun 26 14:46:14] DEBUG[18507][C-00000003] chan_sip.c: Hangup call SIP/vr1a885-00000002, SIP callid 4f95e217710a42279ebc3b52d4d2a34a [Jun 26 14:46:14] DEBUG[18507][C-00000003] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6c1976c' [Jun 26 14:46:14] DEBUG[18424] devicestate.c: No provider found, checking channel drivers for sip - vr1a885 [Jun 26 14:46:14] DEBUG[18424] chan_sip.c: Checking device state for peer vr1a885 [Jun 26 14:46:14] DEBUG[18424] devicestate.c: Checking if I can find provider for "Custom" - number: agent_2 [Jun 26 14:46:14] DEBUG[18424] devicestate.c: Checking provider Custom with Custom [Jun 26 14:46:14] DEBUG[18424] db.c: Unable to find key 'agent_2' in family 'CustomDevstate' [Jun 26 14:46:14] DEBUG[18424] app_queue.c: Extension '885@subscribe_1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 26 14:46:14] DEBUG[18480] 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:46:14] DEBUG[18423] cdr.c: Finalized CDR for SIP/vr1a885-00000002 - start 1435322765.558052 answer 0.000000 end 1435322774.322806 dispo NO ANSWER [Jun 26 14:46:14] DEBUG[18423] cdr.c: Finalized CDR for SIP/vr1a884-00000003 - start 1435322765.608671 answer 0.000000 end 1435322774.322823 dispo NO ANSWER [Jun 26 14:46:14] DEBUG[18423] cdr.c: CDR for SIP/vr1a884-00000003 is dialed and has no Party B; discarding [Jun 26 14:46:14] DEBUG[18408] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jun 26 14:46:14] DEBUG[18420] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:46:14] DEBUG[18420] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:46:14] DEBUG[18420] devicestate.c: Changing state for SIP/vr1a884 - state 1 (Not in use) [Jun 26 14:46:14] DEBUG[18420] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:46:14] DEBUG[18420] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:46:14] DEBUG[18420] devicestate.c: Changing state for SIP/vr1a884 - state 1 (Not in use) [Jun 26 14:46:14] DEBUG[18420] devicestate.c: No provider found, checking channel drivers for SIP - vr1a885 [Jun 26 14:46:14] DEBUG[18420] chan_sip.c: Checking device state for peer vr1a885 [Jun 26 14:46:14] DEBUG[18420] devicestate.c: Changing state for SIP/vr1a885 - state 1 (Not in use) [Jun 26 14:46:14] DEBUG[18480] 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:46:14] DEBUG[18424] devicestate.c: No provider found, checking channel drivers for sip - vr1a884 [Jun 26 14:46:14] DEBUG[18424] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:46:14] DEBUG[18424] devicestate.c: Checking if I can find provider for "Custom" - number: agent_1 [Jun 26 14:46:14] DEBUG[18424] devicestate.c: Checking provider Custom with Custom [Jun 26 14:46:14] DEBUG[18424] db.c: Unable to find key 'agent_1' in family 'CustomDevstate' [Jun 26 14:46:14] DEBUG[18424] app_queue.c: Extension '884@subscribe_1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 26 14:46:14] DEBUG[18445] chan_sip.c: = Looking for Call ID: 4f95e217710a42279ebc3b52d4d2a34a (Checking From) --From tag b1346184fe4343b7a0027ce8f0ee0663 --To-tag as5915e366 [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: Stopping retransmission on '4f95e217710a42279ebc3b52d4d2a34a' of Response 606: Match Found [Jun 26 14:46:14] DEBUG[18445] chan_sip.c: Session timer stopped: -1 - 4f95e217710a42279ebc3b52d4d2a34a [Jun 26 14:46:14] DEBUG[18445] chan_sip.c: Destroying SIP dialog 4f95e217710a42279ebc3b52d4d2a34a [Jun 26 14:46:14] DEBUG[18445] rtp_engine.c: Destroyed RTP instance '0xb6c1976c' [Jun 26 14:46:14] DEBUG[18445] chan_sip.c: = Looking for Call ID: 1289a4917def18c5479ac9782231a6c0@ip_pbx:5060 (Checking To) --From tag as455adfae --To-tag 3100233905 [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: Acked pending invite 102 [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: Stopping retransmission on '1289a4917def18c5479ac9782231a6c0@ip_pbx:5060' of Request 102: Match Found [Jun 26 14:46:14] DEBUG[18445] chan_sip.c: = Looking for Call ID: 1289a4917def18c5479ac9782231a6c0@ip_pbx:5060 (Checking To) --From tag as455adfae --To-tag 3100233905 [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: Stopping retransmission on '1289a4917def18c5479ac9782231a6c0@ip_pbx:5060' of Request 102: Match Found [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: SIP response 487 to standard invite [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: Trying to put 'ACK sip:vr1' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:46:14] DEBUG[18445][C-00000003] chan_sip.c: Updating call counter for outgoing call [Jun 26 14:46:14] DEBUG[18420] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:46:14] DEBUG[18420] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:46:14] DEBUG[18420] devicestate.c: Changing state for SIP/vr1a884 - state 1 (Not in use) [Jun 26 14:46:16] DEBUG[18445] chan_sip.c: Auto destroying SIP dialog '2aedf99204f7a274' [Jun 26 14:46:16] DEBUG[18445] chan_sip.c: Destroying SIP dialog 2aedf99204f7a274 [Jun 26 14:46:16] VERBOSE[18504] asterisk.c: Remote UNIX connection disconnected [Jun 26 14:46:20] DEBUG[18445] chan_sip.c: Auto destroying SIP dialog '1289a4917def18c5479ac9782231a6c0@ip_pbx:5060' [Jun 26 14:46:20] DEBUG[18445] chan_sip.c: Destroying SIP dialog 1289a4917def18c5479ac9782231a6c0@ip_pbx:5060 [Jun 26 14:46:20] DEBUG[18445] rtp_engine.c: Destroyed RTP instance '0x991fe7c' [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: = Looking for Call ID: 2aedf99204f7a274 (Checking From) --From tag ea2141f90a --To-tag [Jun 26 14:46:29] DEBUG[18445] acl.c: For destination 'ip_sip_called', our source address is 'ip_pbx'. [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:46:29] DEBUG[18445] netsock2.c: Splitting 'ip_sip_called:5060' into... [Jun 26 14:46:29] DEBUG[18445] netsock2.c: ...host 'ip_sip_called' and port '5060'. [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: Allocating new SIP dialog for 2aedf99204f7a274 - REGISTER (No RTP) [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 26 14:46:29] DEBUG[18445] netsock2.c: Splitting 'ip_sip_called:5060' into... [Jun 26 14:46:29] DEBUG[18445] netsock2.c: ...host 'ip_sip_called' and port '5060'. [Jun 26 14:46:29] DEBUG[18445] netsock2.c: Splitting 'test_pbx:5060' into... [Jun 26 14:46:29] DEBUG[18445] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: = Looking for Call ID: 2aedf99204f7a274 (Checking From) --From tag ea2141f90a --To-tag [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 26 14:46:29] DEBUG[18445] netsock2.c: Splitting 'ip_sip_called:5060' into... [Jun 26 14:46:29] DEBUG[18445] netsock2.c: ...host 'ip_sip_called' and port '5060'. [Jun 26 14:46:29] DEBUG[18445] netsock2.c: Splitting 'test_pbx:5060' into... [Jun 26 14:46:29] DEBUG[18445] netsock2.c: ...host 'test_pbx' and port ''. [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: build_path: do not use Path headers [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: Allocating new SIP dialog for 666915b94e113b01618dccfd657e0b88@ip_pbx:5060 - OPTIONS (No RTP) [Jun 26 14:46:29] DEBUG[18445] acl.c: For destination 'ip_sip_called', our source address is 'ip_pbx'. [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: Setting AST_TRANSPORT_UDP with address ip_pbx:5060 [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: SIP call-id changed from '666915b94e113b01618dccfd657e0b88@ip_pbx:5060' to '47bc65a1044265ec53e828421b743e2e@ip_pbx:5060' [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: Initializing initreq for method OPTIONS - callid 47bc65a1044265ec53e828421b743e2e@ip_pbx:5060 [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for ip_sip_called:5060 [Jun 26 14:46:29] DEBUG[18420] devicestate.c: No provider found, checking channel drivers for SIP - vr1a884 [Jun 26 14:46:29] DEBUG[18420] chan_sip.c: Checking device state for peer vr1a884 [Jun 26 14:46:29] DEBUG[18420] devicestate.c: Changing state for SIP/vr1a884 - state 1 (Not in use) [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: = Looking for Call ID: 47bc65a1044265ec53e828421b743e2e@ip_pbx:5060 (Checking To) --From tag as4b243651 --To-tag 2641813102 [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: Stopping retransmission on '47bc65a1044265ec53e828421b743e2e@ip_pbx:5060' of Request 102: Match Found [Jun 26 14:46:29] DEBUG[18445] chan_sip.c: Destroying SIP dialog 47bc65a1044265ec53e828421b743e2e@ip_pbx:5060