benchmark-subject-do*CLI> <--- SIP read from UDP:85.24.248.224:5060 ---> INVITE sip:5005@104.248.244.68 SIP/2.0 Call-ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 CSeq: 1 INVITE From: "testbenchDO" ;tag=232bcba0 To: Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-8c8a925a5f4309e9afd382957e732381 Max-Forwards: 70 Contact: "testbenchDO" User-Agent: Jitsi2.10.5550Mac OS X Content-Type: application/sdp Content-Length: 580 v=0 o=testbenchDO-jitsi.org 0 0 IN IP4 85.24.248.224 s=- c=IN IP4 85.24.248.224 t=0 0 m=audio 5018 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=extmap:1 urn:ietf:params:rtp-hdrext:csrc-audio-level a=extmap:2 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=rtcp-xr:voip-metrics m=video 5020 RTP/AVP 96 99 a=recvonly a=rtpmap:96 H264/90000 a=fmtp:96 profile-level-id=4DE01f;packetization-mode=1 a=imageattr:96 send * recv [x=[1:1920],y=[1:1200]] a=rtpmap:99 H264/90000 a=fmtp:99 profile-level-id=4DE01f a=imageattr:99 send * recv [x=[1:1920],y=[1:1200]] <-------------> [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 0 [ 38]: INVITE sip:5005@104.248.244.68 SIP/2.0 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 1 [ 57]: Call-ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 2 [ 14]: CSeq: 1 INVITE [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 3 [ 65]: From: "testbenchDO" ;tag=232bcba0 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 4 [ 29]: To: [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 5 [ 90]: Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-8c8a925a5f4309e9afd382957e732381 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 6 [ 16]: Max-Forwards: 70 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 7 [104]: Contact: "testbenchDO" [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 8 [ 34]: User-Agent: Jitsi2.10.5550Mac OS X [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 9 [ 29]: Content-Type: application/sdp [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 10 [ 19]: Content-Length: 580 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 11 [ 0]: [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 0 [ 3]: v=0 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 1 [ 48]: o=testbenchDO-jitsi.org 0 0 IN IP4 85.24.248.224 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 2 [ 3]: s=- [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 3 [ 22]: c=IN IP4 85.24.248.224 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 4 [ 5]: t=0 0 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 5 [ 24]: m=audio 5018 RTP/AVP 0 8 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 8 [ 54]: a=extmap:1 urn:ietf:params:rtp-hdrext:csrc-audio-level [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 9 [ 54]: a=extmap:2 urn:ietf:params:rtp-hdrext:ssrc-audio-level [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 10 [ 22]: a=rtcp-xr:voip-metrics [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 11 [ 26]: m=video 5020 RTP/AVP 96 99 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 12 [ 10]: a=recvonly [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 13 [ 22]: a=rtpmap:96 H264/90000 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 14 [ 54]: a=fmtp:96 profile-level-id=4DE01f;packetization-mode=1 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 15 [ 50]: a=imageattr:96 send * recv [x=[1:1920],y=[1:1200]] [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 16 [ 22]: a=rtpmap:99 H264/90000 [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 17 [ 33]: a=fmtp:99 profile-level-id=4DE01f [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9968 parse_request: Body 18 [ 50]: a=imageattr:99 send * recv [x=[1:1920],y=[1:1200]] --- (11 headers 19 lines) --- [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9461 __find_call: = Looking for Call ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 (Checking From) --From tag 232bcba0 --To-tag [2018-10-18 15:16:37.969] DEBUG[6588]: acl.c:990 ast_ouraddrfor: For destination '85.24.248.224', our source address is '104.248.244.68'. [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:3953 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 104.248.244.68:5060 [2018-10-18 15:16:37.969] DEBUG[6588]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '85.24.248.224:5060' into... [2018-10-18 15:16:37.969] DEBUG[6588]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '85.24.248.224' and port '5060'. Sending to 85.24.248.224:5060 (NAT) [2018-10-18 15:16:37.969] DEBUG[6588]: chan_sip.c:9054 __sip_alloc: Allocating new SIP dialog for 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 - INVITE (No RTP) [2018-10-18 15:16:37.969] DEBUG[6588][C-00000003]: chan_sip.c:29051 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '85.24.248.224:5060' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '85.24.248.224' and port '5060'. Sending to 85.24.248.224:5060 (NAT) [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:26493 handle_request_invite: Initializing initreq for method INVITE - callid 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 Using INVITE request as basis request - 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '104.248.244.68' and port ''. Found peer 'testbenchDO' for 'testbenchDO' from 85.24.248.224:5060 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: rtp_engine.c:511 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fb91001d9c8' [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: res_rtp_asterisk.c:3492 rtp_allocate_transport: Allocated port 46528 for RTP instance '0x7fb91001d9c8' [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: res_rtp_asterisk.c:3520 rtp_allocate_transport: Creating ICE session [::]:46528 (46528) for RTP instance '0x7fb91001d9c8' [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::f412:50ff:fed2:a08e' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::f412:50ff:fed2:a08e' and port ''. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::f412:50ff:fed2:a08e' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::f412:50ff:fed2:a08e' and port ''. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '104.248.244.68' and port ''. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '104.248.244.68' and port ''. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '10.19.0.7' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '10.19.0.7' and port ''. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '10.19.0.7' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '10.19.0.7' and port ''. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: rtp_engine.c:528 ast_rtp_instance_new: RTP instance '0x7fb91001d9c8' is setup and ready to go [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'benchmark-subject-do' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'benchmark-subject-do' and port ''. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: res_rtp_asterisk.c:7255 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fb91001d9c8' == Using SIP RTP CoS mark 5 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:5841 do_setnat: Setting NAT on RTP to On [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10367 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10367 process_sdp: Processing session-level SDP o=testbenchDO-jitsi.org 0 0 IN IP4 85.24.248.224... OK. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10367 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '85.24.248.224' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '85.24.248.224' and port ''. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10367 process_sdp: Processing session-level SDP c=IN IP4 85.24.248.224... OK. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10367 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 0 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: rtp_engine.c:1304 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7fb8cf82ef80 Found RTP audio format 8 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: rtp_engine.c:1304 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7fb8cf82ef80 Found audio description format PCMU for ID 0 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. Found audio description format PCMA for ID 8 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (audio) SDP a=extmap:1 urn:ietf:params:rtp-hdrext:csrc-audio-level... UNSUPPORTED OR FAILED. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (audio) SDP a=extmap:2 urn:ietf:params:rtp-hdrext:ssrc-audio-level... UNSUPPORTED OR FAILED. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (audio) SDP a=rtcp-xr:voip-metrics... UNSUPPORTED OR FAILED. Found RTP video format 96 Found RTP video format 99 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:34214 process_crypto: Received offer with crypto line for media stream that is not enabled [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (video) SDP a=recvonly... UNSUPPORTED OR FAILED. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:34214 process_crypto: Received offer with crypto line for media stream that is not enabled Found video description format H264 for ID 96 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (video) SDP a=rtpmap:96 H264/90000... OK. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:34214 process_crypto: Received offer with crypto line for media stream that is not enabled [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (video) SDP a=fmtp:96 profile-level-id=4DE01f;packetization-mode=1... OK. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:34214 process_crypto: Received offer with crypto line for media stream that is not enabled [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (video) SDP a=imageattr:96 send * recv [x=[1:1920],y=[1:1200]]... UNSUPPORTED OR FAILED. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:34214 process_crypto: Received offer with crypto line for media stream that is not enabled Found video description format H264 for ID 99 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (video) SDP a=rtpmap:99 H264/90000... OK. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:34214 process_crypto: Received offer with crypto line for media stream that is not enabled [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (video) SDP a=fmtp:99 profile-level-id=4DE01f... UNSUPPORTED OR FAILED. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:34214 process_crypto: Received offer with crypto line for media stream that is not enabled [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (video) SDP a=imageattr:99 send * recv [x=[1:1920],y=[1:1200]]... UNSUPPORTED OR FAILED. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: rtp_engine.c:1268 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 0 (0x7fb9100144a0) from 0x7fb8cf82ef80 to 0x7fb8cf82ef80 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: rtp_engine.c:1268 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 8 (0x7fb910013450) from 0x7fb8cf82ef80 to 0x7fb8cf82ef80 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: rtp_engine.c:1268 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 96 (0x7fb91004acb0) from 0x7fb8cf82f000 to 0x7fb8cf82f000 Capabilities: us - (opus|silk16|ulaw|alaw), peer - audio=(ulaw|alaw)/video=(h264)/text=(nothing), combined - (ulaw|alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing) [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: acl.c:990 ast_ouraddrfor: For destination '85.24.248.224', our source address is '104.248.244.68'. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: res_rtp_asterisk.c:7326 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fb91001d9c8' > 0x7fb910024670 -- Strict RTP learning after remote address set to: 85.24.248.224:5018 Peer audio RTP is at port 85.24.248.224:5018 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: rtp_engine.c:1105 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 0 (0x7fb9100144a0) from 0x7fb8cf82ef80 to 0x7fb91001dba0 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: rtp_engine.c:1105 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 8 (0x7fb910013450) from 0x7fb8cf82ef80 to 0x7fb91001dba0 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: rtp_engine.c:1190 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 0 (0x7fb9100144a0) from 0x7fb8cf82ef80 to 0x7fb91001dba0 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: rtp_engine.c:1190 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 8 (0x7fb910013450) from 0x7fb8cf82ef80 to 0x7fb91001dba0 [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: res_rtp_asterisk.c:7154 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fb91001d9c8' [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:11146 process_sdp: We're settling with these formats: (ulaw|alaw) [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:26625 handle_request_invite: Checking SIP call limits for device testbenchDO [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:6810 update_call_counter: Updating call counter for incoming call [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '104.248.244.68' and port ''. [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '104.248.244.68' and port ''. Looking for 5005 in default (domain 104.248.244.68) [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: channel.c:989 __ast_channel_alloc_ap: Channel 0x7fb910030cf8 'SIP/testbenchDO-00000004' allocated [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:8207 sip_new: *** Our native formats are (ulaw) [2018-10-18 15:16:37.970] DEBUG[6588][C-00000003]: chan_sip.c:8208 sip_new: *** Joint capabilities are (ulaw|alaw) [2018-10-18 15:16:37.971] DEBUG[6588][C-00000003]: chan_sip.c:8209 sip_new: *** Our capabilities are (opus|silk16|ulaw|alaw) [2018-10-18 15:16:37.971] DEBUG[6588][C-00000003]: chan_sip.c:8210 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [2018-10-18 15:16:37.971] DEBUG[6588][C-00000003]: chan_sip.c:8243 sip_new: This channel will not be able to handle video. sip_route_dump: route/path hop: [2018-10-18 15:16:37.971] DEBUG[6588][C-00000003]: chan_sip.c:26830 handle_request_invite: SIP/testbenchDO-00000004: New call is still down.... Trying... <--- Transmitting (NAT) to 85.24.248.224:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-8c8a925a5f4309e9afd382957e732381;received=85.24.248.224;rport=5060 From: "testbenchDO" ;tag=232bcba0 To: Call-ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 CSeq: 1 INVITE Server: Funbers Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: Content-Length: 0 <------------> [2018-10-18 15:16:37.971] DEBUG[6588][C-00000003]: chan_sip.c:3796 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 85.24.248.224:5060 [2018-10-18 15:16:37.971] DEBUG[6619][C-00000003]: pbx.c:2917 pbx_extension_helper: Launching 'NoOp' -- Executing [5005@default:1] NoOp("SIP/testbenchDO-00000004", "============= LOAD TEST ==============") in new stack [2018-10-18 15:16:37.971] DEBUG[6619][C-00000003]: pbx.c:2917 pbx_extension_helper: Launching 'Wait' -- Executing [5005@default:2] Wait("SIP/testbenchDO-00000004", "2") in new stack [2018-10-18 15:16:37.973] DEBUG[6560]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for SIP - testbenchDO [2018-10-18 15:16:37.973] DEBUG[6560]: chan_sip.c:30587 sip_devicestate: Checking device state for peer testbenchDO [2018-10-18 15:16:37.973] DEBUG[6560]: devicestate.c:466 do_state_change: Changing state for SIP/testbenchDO - state 1 (Not in use) [2018-10-18 15:16:38.629] DEBUG[6583]: res_pjsip_registrar.c:1176 check_expiration_thread: Woke up at 1539875798 Interval: 30 [2018-10-18 15:16:38.629] DEBUG[6583]: res_pjsip_registrar.c:1183 check_expiration_thread: Expiring 0 contacts [2018-10-18 15:16:39.971] DEBUG[6619][C-00000003]: pbx.c:2917 pbx_extension_helper: Launching 'Progress' -- Executing [5005@default:3] Progress("SIP/testbenchDO-00000004", "") in new stack [2018-10-18 15:16:39.971] DEBUG[6619][C-00000003]: chan_sip.c:13572 add_sdp: ** Our capability: (ulaw|alaw) Video flag: False Text flag: True [2018-10-18 15:16:39.971] DEBUG[6619][C-00000003]: chan_sip.c:13573 add_sdp: ** Our prefcodec: (nothing) Audio is at 46528 Adding codec ulaw to SDP Adding codec alaw to SDP [2018-10-18 15:16:39.971] DEBUG[6619][C-00000003]: chan_sip.c:13744 add_sdp: -- Done with adding codecs to SDP [2018-10-18 15:16:39.971] DEBUG[6619][C-00000003]: chan_sip.c:13769 add_sdp: Setting framing on incoming call: 20 [2018-10-18 15:16:39.971] DEBUG[6619][C-00000003]: chan_sip.c:13963 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw) <--- Transmitting (NAT) to 85.24.248.224:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-8c8a925a5f4309e9afd382957e732381;received=85.24.248.224;rport=5060 From: "testbenchDO" ;tag=232bcba0 To: ;tag=as1d6a35d6 Call-ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 CSeq: 1 INVITE Server: Funbers Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 246 v=0 o=root 851288847 851288847 IN IP4 104.248.244.68 s=Asterisk PBX 16.0.0 c=IN IP4 104.248.244.68 t=0 0 m=audio 46528 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=ptime:20 a=maxptime:150 a=sendrecv m=video 0 RTP/AVP 96 99 <------------> [2018-10-18 15:16:39.971] DEBUG[6619][C-00000003]: chan_sip.c:3796 __sip_xmit: Trying to put 'SIP/2.0 183' onto UDP socket destined for 85.24.248.224:5060 [2018-10-18 15:16:39.971] DEBUG[6619][C-00000003]: pbx.c:2917 pbx_extension_helper: Launching 'Wait' -- Executing [5005@default:4] Wait("SIP/testbenchDO-00000004", "4") in new stack > 0x7fb910024670 -- Strict RTP switching to RTP target address 85.24.248.224:5018 as source [2018-10-18 15:16:41.624] DEBUG[6588]: chan_sip.c:4404 __sip_autodestruct: Auto destroying SIP dialog 'b6351309a4d0983d084f0bfc7b114185@0:0:0:0:0:0:0:0' [2018-10-18 15:16:41.624] DEBUG[6588]: chan_sip.c:6637 sip_pvt_dtor: Destroying SIP dialog b6351309a4d0983d084f0bfc7b114185@0:0:0:0:0:0:0:0 Really destroying SIP dialog 'b6351309a4d0983d084f0bfc7b114185@0:0:0:0:0:0:0:0' Method: OPTIONS [2018-10-18 15:16:42.660] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:5603 ast_rtcp_interpret: Got RTCP report of 128 bytes from 85.24.248.224:5019 > 0x7fb910024670 -- Strict RTP learning complete - Locking on source address 85.24.248.224:5018 [2018-10-18 15:16:43.972] DEBUG[6619][C-00000003]: pbx.c:2917 pbx_extension_helper: Launching 'AGI' -- Executing [5005@default:5] AGI("SIP/testbenchDO-00000004", "/etc/asterisk/startCall.php") in new stack -- Launched AGI Script /etc/asterisk/startCall.php [2018-10-18 15:16:43.995] DEBUG[6619][C-00000003]: pbx_variables.c:376 ast_str_retrieve_variable: Result of 'ANI' is NULL -- AGI Script /etc/asterisk/startCall.php completed, returning 0 [2018-10-18 15:16:43.997] DEBUG[6619][C-00000003]: pbx_variables.c:379 ast_str_retrieve_variable: Result of 'DSTVAR' is 'server2' [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: pbx.c:2917 pbx_extension_helper: Launching 'Dial' -- Executing [5005@default:6] Dial("SIP/testbenchDO-00000004", "sip/server2/5003") in new stack [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: chan_sip.c:30694 sip_request_call: Asked to create a SIP channel with formats: (ulaw) [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: chan_sip.c:9054 __sip_alloc: Allocating new SIP dialog for 42d74b415753868061f7460c6a7a3422@127.0.1.1:5060 - INVITE (No RTP) [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: rtp_engine.c:511 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fb92c007638' [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:3492 rtp_allocate_transport: Allocated port 12216 for RTP instance '0x7fb92c007638' [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:3520 rtp_allocate_transport: Creating ICE session [::]:12216 (12216) for RTP instance '0x7fb92c007638' [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::f412:50ff:fed2:a08e' into... [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::f412:50ff:fed2:a08e' and port ''. [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::f412:50ff:fed2:a08e' into... [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::f412:50ff:fed2:a08e' and port ''. [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '104.248.244.68' and port ''. [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '104.248.244.68' and port ''. [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '10.19.0.7' into... [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '10.19.0.7' and port ''. [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '10.19.0.7' into... [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '10.19.0.7' and port ''. [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: rtp_engine.c:528 ast_rtp_instance_new: RTP instance '0x7fb92c007638' is setup and ready to go [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'benchmark-subject-do' into... [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'benchmark-subject-do' and port ''. [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:7255 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fb92c007638' == Using SIP RTP CoS mark 5 [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: chan_sip.c:5841 do_setnat: Setting NAT on RTP to On [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: chan_sip.c:3563 obproxy_get: OBPROXY: Not applying OBproxy to this call [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: acl.c:990 ast_ouraddrfor: For destination '18.184.180.200', our source address is '104.248.244.68'. [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: chan_sip.c:3953 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 104.248.244.68:5060 [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: chan_sip.c:5841 do_setnat: Setting NAT on RTP to On [2018-10-18 15:16:43.998] DEBUG[6619][C-00000003]: chan_sip.c:8843 change_callid_pvt: SIP call-id changed from '42d74b415753868061f7460c6a7a3422@127.0.1.1:5060' to '2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060' [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: channel.c:989 __ast_channel_alloc_ap: Channel 0x7fb92c00ff58 'SIP/server2-00000005' allocated [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:8207 sip_new: *** Our native formats are (ulaw) [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:8208 sip_new: *** Joint capabilities are (ulaw) [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:8209 sip_new: *** Our capabilities are (ulaw|alaw) [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:8210 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:8212 sip_new: *** Our preferred formats from the incoming channel are (ulaw) [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:8243 sip_new: This channel will not be able to handle video. [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: channel_internal_api.c:770 ast_channel_callid_set: Channel Call ID changing from [C-00000003] to [C-00000003] [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:6521 sip_call: Outgoing Call for 5003 [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:6810 update_call_counter: Updating call counter for outgoing call [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:13572 add_sdp: ** Our capability: (ulaw|alaw) Video flag: False Text flag: False [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:13573 add_sdp: ** Our prefcodec: (ulaw) Audio is at 12216 Adding codec ulaw to SDP Adding codec alaw to SDP Adding non-codec 0x1 (telephone-event) to SDP [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:13744 add_sdp: -- Done with adding codecs to SDP [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:13963 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw) [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:3439 initialize_initreq: Initializing initreq for method INVITE - callid 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 0 [ 38]: INVITE sip:5003@18.184.180.200 SIP/2.0 [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK6120a0bc;rport [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 2 [ 16]: Max-Forwards: 70 [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 3 [ 67]: From: "testbenchDO" ;tag=as7f0f641c [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 4 [ 29]: To: [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 5 [ 46]: Contact: [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 6 [ 61]: Call-ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 8 [ 19]: User-Agent: Funbers [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 9 [ 35]: Date: Thu, 18 Oct 2018 15:16:43 GMT [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 10 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 11 [ 26]: Supported: replaces, timer [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:9931 parse_request: Header 12 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 18.184.180.200:5060: INVITE sip:5003@18.184.180.200 SIP/2.0 Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK6120a0bc;rport Max-Forwards: 70 From: "testbenchDO" ;tag=as7f0f641c To: Contact: Call-ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 CSeq: 102 INVITE User-Agent: Funbers Date: Thu, 18 Oct 2018 15:16:43 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 277 v=0 o=root 832999246 832999246 IN IP4 104.248.244.68 s=Asterisk PBX 16.0.0 c=IN IP4 104.248.244.68 t=0 0 m=audio 12216 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:4309 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #2 [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: chan_sip.c:3796 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 18.184.180.200:5060 -- Called sip/server2/5003 [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/server2-00000005 setting read format path: ulaw -> ulaw [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/testbenchDO-00000004 setting write format path: ulaw -> ulaw [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/testbenchDO-00000004 setting read format path: ulaw -> ulaw [2018-10-18 15:16:43.999] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/server2-00000005 setting write format path: ulaw -> ulaw <--- SIP read from UDP:18.184.180.200:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK6120a0bc;received=104.248.244.68;rport=5060 From: "testbenchDO" ;tag=as7f0f641c To: Call-ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 CSeq: 102 INVITE Server: Funbers Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 <-------------> [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 1 [ 94]: Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK6120a0bc;received=104.248.244.68;rport=5060 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 2 [ 67]: From: "testbenchDO" ;tag=as7f0f641c [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 3 [ 29]: To: [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 4 [ 61]: Call-ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 6 [ 15]: Server: Funbers [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 7 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 8 [ 26]: Supported: replaces, timer [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 9 [ 35]: Session-Expires: 1800;refresher=uas [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 10 [ 39]: Contact: [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 11 [ 17]: Content-Length: 0 --- (12 headers 0 lines) --- [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9461 __find_call: = Looking for Call ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 (Checking To) --From tag as7f0f641c --To-tag [2018-10-18 15:16:44.009] DEBUG[6588][C-00000003]: chan_sip.c:4614 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #2 - INVITE (got response) [2018-10-18 15:16:44.009] DEBUG[6588][C-00000003]: chan_sip.c:4621 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060' Request 102: Found [2018-10-18 15:16:44.009] DEBUG[6588][C-00000003]: chan_sip.c:23889 handle_response_invite: SIP response 100 to standard invite <--- SIP read from UDP:18.184.180.200:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK6120a0bc;received=104.248.244.68;rport=5060 From: "testbenchDO" ;tag=as7f0f641c To: ;tag=as70a84e8c Call-ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 CSeq: 102 INVITE Server: Funbers Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Type: application/sdp Require: timer Content-Length: 253 v=0 o=root 456679256 456679256 IN IP4 18.184.180.200 s=Asterisk PBX 16.0.0 c=IN IP4 18.184.180.200 t=0 0 m=audio 20558 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv <-------------> [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 1 [ 94]: Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK6120a0bc;received=104.248.244.68;rport=5060 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 2 [ 67]: From: "testbenchDO" ;tag=as7f0f641c [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 3 [ 44]: To: ;tag=as70a84e8c [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 4 [ 61]: Call-ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 6 [ 15]: Server: Funbers [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 7 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 8 [ 26]: Supported: replaces, timer [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 9 [ 35]: Session-Expires: 1800;refresher=uas [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 10 [ 39]: Contact: [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 11 [ 29]: Content-Type: application/sdp [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 12 [ 14]: Require: timer [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 13 [ 19]: Content-Length: 253 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 14 [ 0]: [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 0 [ 3]: v=0 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 1 [ 48]: o=root 456679256 456679256 IN IP4 18.184.180.200 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 2 [ 21]: s=Asterisk PBX 16.0.0 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 3 [ 23]: c=IN IP4 18.184.180.200 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 4 [ 5]: t=0 0 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 5 [ 27]: m=audio 20558 RTP/AVP 0 101 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [2018-10-18 15:16:44.009] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [2018-10-18 15:16:44.010] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [2018-10-18 15:16:44.010] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 9 [ 10]: a=ptime:20 [2018-10-18 15:16:44.010] DEBUG[6588]: chan_sip.c:9931 parse_request: Body 10 [ 14]: a=maxptime:150 [2018-10-18 15:16:44.010] DEBUG[6588]: chan_sip.c:9968 parse_request: Body 11 [ 10]: a=sendrecv --- (14 headers 12 lines) --- [2018-10-18 15:16:44.010] DEBUG[6588]: chan_sip.c:9461 __find_call: = Looking for Call ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 (Checking To) --From tag as7f0f641c --To-tag as70a84e8c [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:4564 __sip_ack: Acked pending invite 102 [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:4580 __sip_ack: Stopping retransmission on '2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060' of Request 102: Match Found [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:23889 handle_response_invite: SIP response 200 to standard invite [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:10367 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:10367 process_sdp: Processing session-level SDP o=root 456679256 456679256 IN IP4 18.184.180.200... OK. [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:10367 process_sdp: Processing session-level SDP s=Asterisk PBX 16.0.0... UNSUPPORTED OR FAILED. [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '18.184.180.200' into... [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '18.184.180.200' and port ''. [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:10367 process_sdp: Processing session-level SDP c=IN IP4 18.184.180.200... OK. [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:10367 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 0 [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: rtp_engine.c:1304 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7fb8cf82ea40 Found RTP audio format 101 Found audio description format PCMU for ID 0 [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. Found audio description format telephone-event for ID 101 [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (audio) SDP a=maxptime:150... UNSUPPORTED OR FAILED. [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:10838 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. Capabilities: us - (ulaw|alaw), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: res_rtp_asterisk.c:1061 ast_rtp_ice_set_role: Set role to CONTROLLING (0x7fb92c007638) [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: res_rtp_asterisk.c:1064 ast_rtp_ice_set_role: Set role failed; no ice instance (0x7fb92c007638) [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: acl.c:990 ast_ouraddrfor: For destination '18.184.180.200', our source address is '104.248.244.68'. [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: res_rtp_asterisk.c:7326 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fb92c007638' > 0x7fb92c00ba60 -- Strict RTP learning after remote address set to: 18.184.180.200:20558 Peer audio RTP is at port 18.184.180.200:20558 [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: rtp_engine.c:1190 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 0 (0x7fb910023ad0) from 0x7fb8cf82ea40 to 0x7fb92c007810 [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: rtp_engine.c:1190 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 101 (0x7fb910009630) from 0x7fb8cf82ea40 to 0x7fb92c007810 [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: res_rtp_asterisk.c:7154 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fb92c007638' [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:11146 process_sdp: We're settling with these formats: (ulaw) [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:11153 process_sdp: We have an owner, now see if we need to change this call [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:11164 process_sdp: Setting native formats after processing SDP. peer joint formats (ulaw), old nativeformats (ulaw) [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: channel.c:5634 set_format: Channel SIP/server2-00000005 setting read format path: ulaw -> ulaw [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: channel.c:5634 set_format: Channel SIP/server2-00000005 setting write format path: ulaw -> ulaw [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:6810 update_call_counter: Updating call counter for outgoing call sip_route_dump: route/path hop: [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:30197 parse_session_expires: Session-Expires: 1800 [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:30213 parse_session_expires: Refresher: UAS [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:12306 reqprep: Strict routing enforced for session 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 Transmitting (NAT) to 18.184.180.200:5060: ACK sip:5003@18.184.180.200:5060 SIP/2.0 Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK2f2677c8;rport Max-Forwards: 70 From: "testbenchDO" ;tag=as7f0f641c To: ;tag=as70a84e8c Contact: Call-ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 CSeq: 102 ACK User-Agent: Funbers Content-Length: 0 --- [2018-10-18 15:16:44.010] DEBUG[6588][C-00000003]: chan_sip.c:3796 __sip_xmit: Trying to put 'ACK sip:500' onto UDP socket destined for 18.184.180.200:5060 [2018-10-18 15:16:44.010] DEBUG[6588]: chan_sip.c:30124 __start_session_timer: Session timer started: 5 - 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 1768000ms -- SIP/server2-00000005 answered SIP/testbenchDO-00000004 [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: rtp_engine.c:2398 ast_rtp_instance_early_bridge: Setting early bridge SDP of 'SIP/testbenchDO-00000004' with that of 'SIP/server2-00000005' [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/server2-00000005 setting read format path: ulaw -> ulaw [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/testbenchDO-00000004 setting write format path: ulaw -> ulaw [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/testbenchDO-00000004 setting read format path: ulaw -> ulaw [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/server2-00000005 setting write format path: ulaw -> ulaw [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: chan_sip.c:7455 sip_answer: SIP answering channel: SIP/testbenchDO-00000004 [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:3974 ast_rtp_update_source: Setting the marker bit due to a source update [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: chan_sip.c:13572 add_sdp: ** Our capability: (ulaw|alaw) Video flag: False Text flag: True [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: chan_sip.c:13573 add_sdp: ** Our prefcodec: (nothing) Audio is at 46528 Adding codec ulaw to SDP Adding codec alaw to SDP [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: chan_sip.c:13744 add_sdp: -- Done with adding codecs to SDP [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: chan_sip.c:13769 add_sdp: Setting framing on incoming call: 20 [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: chan_sip.c:13963 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw) <--- Reliably Transmitting (NAT) to 85.24.248.224:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-8c8a925a5f4309e9afd382957e732381;received=85.24.248.224;rport=5060 From: "testbenchDO" ;tag=232bcba0 To: ;tag=as1d6a35d6 Call-ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 CSeq: 1 INVITE Server: Funbers Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 246 v=0 o=root 851288847 851288847 IN IP4 104.248.244.68 s=Asterisk PBX 16.0.0 c=IN IP4 104.248.244.68 t=0 0 m=audio 46528 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=ptime:20 a=maxptime:150 a=sendrecv m=video 0 RTP/AVP 96 99 <------------> [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: chan_sip.c:4309 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3 [2018-10-18 15:16:44.010] DEBUG[6619][C-00000003]: chan_sip.c:3796 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 85.24.248.224:5060 [2018-10-18 15:16:44.011] DEBUG[6619][C-00000003]: bridge_native_rtp.c:734 native_rtp_bridge_compatible: Bridge 'b43ca019-3ebf-4f70-a69e-5aa69c345cc6' can not use native RTP bridge as two channels are required [2018-10-18 15:16:44.011] DEBUG[6619][C-00000003]: bridge.c:530 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-10-18 15:16:44.011] DEBUG[6619][C-00000003]: bridge.c:520 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2018-10-18 15:16:44.011] DEBUG[6619][C-00000003]: bridge.c:525 find_best_technology: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [2018-10-18 15:16:44.011] DEBUG[6619][C-00000003]: bridge.c:544 find_best_technology: Chose bridge technology simple_bridge [2018-10-18 15:16:44.011] DEBUG[6619][C-00000003]: bridge.c:827 bridge_base_init: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: calling simple_bridge technology constructor [2018-10-18 15:16:44.011] DEBUG[6619][C-00000003]: bridge.c:835 bridge_base_init: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: calling simple_bridge technology start [2018-10-18 15:16:44.011] DEBUG[6549]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [2018-10-18 15:16:44.011] DEBUG[6560]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for SIP - server2 [2018-10-18 15:16:44.011] DEBUG[6560]: chan_sip.c:30587 sip_devicestate: Checking device state for peer server2 [2018-10-18 15:16:44.011] DEBUG[6560]: devicestate.c:466 do_state_change: Changing state for SIP/server2 - state 1 (Not in use) [2018-10-18 15:16:44.011] DEBUG[6560]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for SIP - testbenchDO [2018-10-18 15:16:44.011] DEBUG[6560]: chan_sip.c:30587 sip_devicestate: Checking device state for peer testbenchDO [2018-10-18 15:16:44.011] DEBUG[6560]: devicestate.c:466 do_state_change: Changing state for SIP/testbenchDO - state 1 (Not in use) [2018-10-18 15:16:44.011] DEBUG[6621][C-00000003]: bridge_channel.c:2829 bridge_channel_internal_join: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: 0x7fb92c022248(SIP/server2-00000005) is joining [2018-10-18 15:16:44.012] DEBUG[6621][C-00000003]: bridge_channel.c:2204 bridge_channel_internal_push_full: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: pushing 0x7fb92c022248(SIP/server2-00000005) -- Channel SIP/server2-00000005 joined 'simple_bridge' basic-bridge [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge_native_rtp.c:734 native_rtp_bridge_compatible: Bridge 'b43ca019-3ebf-4f70-a69e-5aa69c345cc6' can not use native RTP bridge as two channels are required [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge.c:530 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge.c:520 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge.c:520 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge.c:544 find_best_technology: Chose bridge technology simple_bridge [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge.c:1081 smart_bridge_operation: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6 is already using the new technology. [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge.c:443 bridge_channel_complete_join: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: 0x7fb92c022248(SIP/server2-00000005) is joining simple_bridge technology [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:3992 ast_rtp_change_source: Changing ssrc from 79805099 to 1504312612 due to a source change [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge_native_rtp.c:734 native_rtp_bridge_compatible: Bridge 'b43ca019-3ebf-4f70-a69e-5aa69c345cc6' can not use native RTP bridge as two channels are required [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge.c:530 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge.c:520 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge.c:520 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge.c:544 find_best_technology: Chose bridge technology simple_bridge [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: bridge.c:1081 smart_bridge_operation: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6 is already using the new technology. [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge_channel.c:2829 bridge_channel_internal_join: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: 0x7fb92c004608(SIP/testbenchDO-00000004) is joining [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge_channel.c:2204 bridge_channel_internal_push_full: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: pushing 0x7fb92c004608(SIP/testbenchDO-00000004) -- Channel SIP/testbenchDO-00000004 joined 'simple_bridge' basic-bridge [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge 'b43ca019-3ebf-4f70-a69e-5aa69c345cc6'. Checking compatability for channels 'SIP/server2-00000005' and 'SIP/testbenchDO-00000004' [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge_native_rtp.c:628 native_rtp_bridge_compatible_check: Bridge 'b43ca019-3ebf-4f70-a69e-5aa69c345cc6' can not use native RTP bridge as channel 'SIP/server2-00000005' has features which prevent it [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge.c:530 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge.c:520 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge.c:520 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge.c:544 find_best_technology: Chose bridge technology simple_bridge [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge.c:1081 smart_bridge_operation: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6 is already using the new technology. [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge.c:443 bridge_channel_complete_join: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: 0x7fb92c004608(SIP/testbenchDO-00000004) is joining simple_bridge technology [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/testbenchDO-00000004 setting read format path: ulaw -> ulaw [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/server2-00000005 setting write format path: ulaw -> ulaw [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/server2-00000005 setting read format path: ulaw -> ulaw [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: channel.c:5634 set_format: Channel SIP/testbenchDO-00000004 setting write format path: ulaw -> ulaw [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:3992 ast_rtp_change_source: Changing ssrc from 1419886327 to 1707137694 due to a source change [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge 'b43ca019-3ebf-4f70-a69e-5aa69c345cc6'. Checking compatability for channels 'SIP/server2-00000005' and 'SIP/testbenchDO-00000004' [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge_native_rtp.c:628 native_rtp_bridge_compatible_check: Bridge 'b43ca019-3ebf-4f70-a69e-5aa69c345cc6' can not use native RTP bridge as channel 'SIP/server2-00000005' has features which prevent it [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge.c:530 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge.c:520 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge.c:520 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge.c:544 find_best_technology: Chose bridge technology simple_bridge [2018-10-18 15:16:44.013] DEBUG[6619][C-00000003]: bridge.c:1081 smart_bridge_operation: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6 is already using the new technology. [2018-10-18 15:16:44.013] DEBUG[6568]: cdr.c:1463 cdr_object_finalize: Finalized CDR for SIP/server2-00000005 - start 1539875803.999166 answer 1539875804.011189 end 1539875804.013634 dispo ANSWERED [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4863 ast_rtp_write: Ooh, format changed from none to ulaw [2018-10-18 15:16:44.013] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4643 rtp_raw_write: Starting RTCP transmission on RTP instance '0x7fb92c007638' <--- SIP read from UDP:85.24.248.224:5060 ---> ACK sip:5005@104.248.244.68:5060 SIP/2.0 Call-ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 CSeq: 1 ACK Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-1d2b3c78e3aefb76d927345358f0120a From: "testbenchDO" ;tag=232bcba0 To: ;tag=as1d6a35d6 Max-Forwards: 70 Contact: "testbenchDO" User-Agent: Jitsi2.10.5550Mac OS X Content-Length: 0 <-------------> [2018-10-18 15:16:44.043] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 0 [ 40]: ACK sip:5005@104.248.244.68:5060 SIP/2.0 [2018-10-18 15:16:44.044] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 1 [ 57]: Call-ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 [2018-10-18 15:16:44.044] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 2 [ 11]: CSeq: 1 ACK [2018-10-18 15:16:44.044] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 3 [ 90]: Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-1d2b3c78e3aefb76d927345358f0120a [2018-10-18 15:16:44.044] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 4 [ 65]: From: "testbenchDO" ;tag=232bcba0 [2018-10-18 15:16:44.044] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 5 [ 44]: To: ;tag=as1d6a35d6 [2018-10-18 15:16:44.044] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 6 [ 16]: Max-Forwards: 70 [2018-10-18 15:16:44.044] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 7 [104]: Contact: "testbenchDO" [2018-10-18 15:16:44.044] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 8 [ 34]: User-Agent: Jitsi2.10.5550Mac OS X [2018-10-18 15:16:44.044] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [2018-10-18 15:16:44.044] DEBUG[6588]: chan_sip.c:9461 __find_call: = Looking for Call ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 (Checking From) --From tag 232bcba0 --To-tag as1d6a35d6 [2018-10-18 15:16:44.044] DEBUG[6588][C-00000003]: chan_sip.c:29051 handle_incoming: **** Received ACK (6) - Command in SIP ACK [2018-10-18 15:16:44.044] DEBUG[6588][C-00000003]: chan_sip.c:4569 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3 [2018-10-18 15:16:44.044] DEBUG[6588][C-00000003]: chan_sip.c:4580 __sip_ack: Stopping retransmission on '7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0' of Response 1: Match Found [2018-10-18 15:16:44.067] WARNING[6619][C-00000003]: chan_iax2.c:1228 jb_warning_output: Resyncing the jb. last_delay 0, this delay -3887, threshold 1000, new offset 3887 [2018-10-18 15:16:44.111] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:44.529] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame > 0x7fb92c00ba60 -- Strict RTP switching to RTP target address 18.184.180.200:20558 as source [2018-10-18 15:16:45.036] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4863 ast_rtp_write: Ooh, format changed from none to ulaw [2018-10-18 15:16:45.095] WARNING[6621][C-00000003]: chan_iax2.c:1228 jb_warning_output: Resyncing the jb. last_delay 0, this delay 1002, threshold 1000, new offset -1002 [2018-10-18 15:16:45.320] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:5603 ast_rtcp_interpret: Got RTCP report of 104 bytes from 85.24.248.224:5019 [2018-10-18 15:16:45.372] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:45.563] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:46.013] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:46.093] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:46.513] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:46.613] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:47.038] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:47.133] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:47.536] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:47.653] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:47.995] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:48.173] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:48.473] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:48.693] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:48.929] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:49.014] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:5603 ast_rtcp_interpret: Got RTCP report of 100 bytes from 18.184.180.200:20559 > 0x7fb92c00ba60 -- Strict RTP learning complete - Locking on source address 18.184.180.200:20558 [2018-10-18 15:16:49.213] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:49.515] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:49.733] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:50.036] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:50.253] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:50.536] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:50.556] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:5603 ast_rtcp_interpret: Got RTCP report of 104 bytes from 85.24.248.224:5019 [2018-10-18 15:16:50.773] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:51.126] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:51.293] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:51.601] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:51.813] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:52.123] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:52.333] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:52.677] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:52.853] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:53.176] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:53.373] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:53.654] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:53.893] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:54.014] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:5603 ast_rtcp_interpret: Got RTCP report of 100 bytes from 18.184.180.200:20559 [2018-10-18 15:16:54.198] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:54.413] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:54.740] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9054 __sip_alloc: Allocating new SIP dialog for 4f39896d4e14b78e63719ad91871941b@127.0.1.1:5060 - OPTIONS (No RTP) [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:3563 obproxy_get: OBPROXY: Not applying OBproxy to this call [2018-10-18 15:16:54.870] DEBUG[6588]: acl.c:990 ast_ouraddrfor: For destination '85.24.248.224', our source address is '104.248.244.68'. [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:3953 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 104.248.244.68:5060 [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:8843 change_callid_pvt: SIP call-id changed from '4f39896d4e14b78e63719ad91871941b@127.0.1.1:5060' to '27d0241e3151a6927d97fcbb2c8046d2@104.248.244.68:5060' [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:3439 initialize_initreq: Initializing initreq for method OPTIONS - callid 27d0241e3151a6927d97fcbb2c8046d2@104.248.244.68:5060 [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 0 [ 95]: OPTIONS sip:testbenchDO@85.24.248.224:5060;transport=udp;registering_acc=104_248_244_68 SIP/2.0 [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK6036ab87;rport [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 2 [ 16]: Max-Forwards: 70 [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 3 [ 61]: From: "asterisk" ;tag=as7f483d44 [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 4 [ 85]: To: [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 5 [ 43]: Contact: [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 6 [ 61]: Call-ID: 27d0241e3151a6927d97fcbb2c8046d2@104.248.244.68:5060 [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 8 [ 19]: User-Agent: Funbers [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 9 [ 35]: Date: Thu, 18 Oct 2018 15:16:54 GMT [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 10 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 11 [ 26]: Supported: replaces, timer Reliably Transmitting (NAT) to 85.24.248.224:5060: OPTIONS sip:testbenchDO@85.24.248.224:5060;transport=udp;registering_acc=104_248_244_68 SIP/2.0 Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK6036ab87;rport Max-Forwards: 70 From: "asterisk" ;tag=as7f483d44 To: Contact: Call-ID: 27d0241e3151a6927d97fcbb2c8046d2@104.248.244.68:5060 CSeq: 102 OPTIONS User-Agent: Funbers Date: Thu, 18 Oct 2018 15:16:54 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 --- [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:4309 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #21 [2018-10-18 15:16:54.870] DEBUG[6588]: chan_sip.c:3796 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 85.24.248.224:5060 <--- SIP read from UDP:85.24.248.224:5060 ---> SIP/2.0 200 OK CSeq: 102 OPTIONS Call-ID: 27d0241e3151a6927d97fcbb2c8046d2@104.248.244.68:5060 From: "asterisk" ;tag=as7f483d44 To: ;tag=ff568471 Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK6036ab87;rport=5060;received=104.248.244.68 Contact: "testbenchDO" User-Agent: Jitsi2.10.5550Mac OS X Allow: INFO,UPDATE,OPTIONS,MESSAGE,BYE,REFER,SUBSCRIBE,ACK,CANCEL,NOTIFY,INVITE Allow-Events: refer,conference,remote-control,message-summary Content-Length: 0 <-------------> [2018-10-18 15:16:54.901] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [2018-10-18 15:16:54.901] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 1 [ 17]: CSeq: 102 OPTIONS [2018-10-18 15:16:54.901] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 2 [ 61]: Call-ID: 27d0241e3151a6927d97fcbb2c8046d2@104.248.244.68:5060 [2018-10-18 15:16:54.901] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 3 [ 61]: From: "asterisk" ;tag=as7f483d44 [2018-10-18 15:16:54.901] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 4 [ 98]: To: ;tag=ff568471 [2018-10-18 15:16:54.901] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 5 [ 94]: Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK6036ab87;rport=5060;received=104.248.244.68 [2018-10-18 15:16:54.901] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 6 [104]: Contact: "testbenchDO" [2018-10-18 15:16:54.901] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 7 [ 34]: User-Agent: Jitsi2.10.5550Mac OS X [2018-10-18 15:16:54.901] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 8 [ 79]: Allow: INFO,UPDATE,OPTIONS,MESSAGE,BYE,REFER,SUBSCRIBE,ACK,CANCEL,NOTIFY,INVITE [2018-10-18 15:16:54.901] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 9 [ 61]: Allow-Events: refer,conference,remote-control,message-summary [2018-10-18 15:16:54.902] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [2018-10-18 15:16:54.902] DEBUG[6588]: chan_sip.c:9461 __find_call: = Looking for Call ID: 27d0241e3151a6927d97fcbb2c8046d2@104.248.244.68:5060 (Checking To) --From tag as7f483d44 --To-tag ff568471 [2018-10-18 15:16:54.902] DEBUG[6588]: chan_sip.c:4569 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #21 [2018-10-18 15:16:54.902] DEBUG[6588]: chan_sip.c:4580 __sip_ack: Stopping retransmission on '27d0241e3151a6927d97fcbb2c8046d2@104.248.244.68:5060' of Request 102: Match Found [2018-10-18 15:16:54.902] DEBUG[6588]: chan_sip.c:6637 sip_pvt_dtor: Destroying SIP dialog 27d0241e3151a6927d97fcbb2c8046d2@104.248.244.68:5060 Really destroying SIP dialog '27d0241e3151a6927d97fcbb2c8046d2@104.248.244.68:5060' Method: OPTIONS [2018-10-18 15:16:54.933] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:55.357] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:55.453] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:55.856] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:55.973] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:56.326] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:56.493] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:56.559] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:5603 ast_rtcp_interpret: Got RTCP report of 152 bytes from 85.24.248.224:5019 [2018-10-18 15:16:56.826] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:57.013] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:57.304] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:57.533] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:57.805] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:58.053] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:58.227] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:58.573] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:58.706] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame [2018-10-18 15:16:59.014] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:5603 ast_rtcp_interpret: Got RTCP report of 100 bytes from 18.184.180.200:20559 [2018-10-18 15:16:59.093] DEBUG[6619][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb91001d9c8' so dropping frame [2018-10-18 15:16:59.205] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:4829 ast_rtp_write: Received frame with no data for RTP instance '0x7fb92c007638' so dropping frame <--- SIP read from UDP:85.24.248.224:5060 ---> BYE sip:5005@104.248.244.68:5060 SIP/2.0 CSeq: 2 BYE From: "testbenchDO" ;tag=232bcba0 To: ;tag=as1d6a35d6 Call-ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 Max-Forwards: 70 Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-50632855d0b80e07f5b600a2f4fe6d72 Contact: "testbenchDO" User-Agent: Jitsi2.10.5550Mac OS X Content-Length: 0 <-------------> [2018-10-18 15:16:59.420] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 0 [ 40]: BYE sip:5005@104.248.244.68:5060 SIP/2.0 [2018-10-18 15:16:59.420] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 1 [ 11]: CSeq: 2 BYE [2018-10-18 15:16:59.420] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 2 [ 65]: From: "testbenchDO" ;tag=232bcba0 [2018-10-18 15:16:59.420] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 3 [ 44]: To: ;tag=as1d6a35d6 [2018-10-18 15:16:59.420] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 4 [ 57]: Call-ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 [2018-10-18 15:16:59.420] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 5 [ 16]: Max-Forwards: 70 [2018-10-18 15:16:59.420] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 6 [ 90]: Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-50632855d0b80e07f5b600a2f4fe6d72 [2018-10-18 15:16:59.420] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 7 [104]: Contact: "testbenchDO" [2018-10-18 15:16:59.420] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 8 [ 34]: User-Agent: Jitsi2.10.5550Mac OS X [2018-10-18 15:16:59.420] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [2018-10-18 15:16:59.420] DEBUG[6588]: chan_sip.c:9461 __find_call: = Looking for Call ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 (Checking From) --From tag 232bcba0 --To-tag as1d6a35d6 [2018-10-18 15:16:59.420] DEBUG[6588][C-00000003]: chan_sip.c:29051 handle_incoming: **** Received BYE (8) - Command in SIP BYE [2018-10-18 15:16:59.420] DEBUG[6588][C-00000003]: chan_sip.c:27488 handle_request_bye: Initializing initreq for method BYE - callid 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 [2018-10-18 15:16:59.420] DEBUG[6588][C-00000003]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '85.24.248.224:5060' into... [2018-10-18 15:16:59.420] DEBUG[6588][C-00000003]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '85.24.248.224' and port '5060'. Sending to 85.24.248.224:5060 (NAT) [2018-10-18 15:16:59.420] DEBUG[6588][C-00000003]: chan_sip.c:3452 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 Scheduling destruction of SIP dialog '7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0' in 6848 ms (Method: BYE) [2018-10-18 15:16:59.420] DEBUG[6588][C-00000003]: chan_sip.c:27652 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 85.24.248.224:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-50632855d0b80e07f5b600a2f4fe6d72;received=85.24.248.224;rport=5060 From: "testbenchDO" ;tag=232bcba0 To: ;tag=as1d6a35d6 Call-ID: 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 CSeq: 2 BYE Server: Funbers Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 <------------> [2018-10-18 15:16:59.420] DEBUG[6588][C-00000003]: chan_sip.c:3796 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 85.24.248.224:5060 [2018-10-18 15:16:59.420] DEBUG[6619][C-00000003]: bridge_channel.c:289 ast_bridge_channel_leave_bridge_nolock: Setting 0x7fb92c004608(SIP/testbenchDO-00000004) state from:0 to:1 [2018-10-18 15:16:59.420] DEBUG[6619][C-00000003]: bridge_channel.c:2141 bridge_channel_internal_pull: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: pulling 0x7fb92c004608(SIP/testbenchDO-00000004) -- Channel SIP/testbenchDO-00000004 left 'simple_bridge' basic-bridge [2018-10-18 15:16:59.420] DEBUG[6619][C-00000003]: bridge_channel.c:2153 bridge_channel_internal_pull: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: 0x7fb92c004608(SIP/testbenchDO-00000004) is leaving simple_bridge technology [2018-10-18 15:16:59.420] DEBUG[6619][C-00000003]: bridge.c:333 bridge_dissolve: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: dissolving bridge with cause 16(Normal Clearing) [2018-10-18 15:16:59.420] DEBUG[6619][C-00000003]: bridge_channel.c:289 ast_bridge_channel_leave_bridge_nolock: Setting 0x7fb92c022248(SIP/server2-00000005) state from:0 to:2 [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: bridge.c:294 bridge_queue_action_nodup: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: queueing action type:13 sub:1001 [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: bridge.c:1038 smart_bridge_operation: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6 is dissolved, not performing smart bridge operation. [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: app_dial.c:3224 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: pbx.c:4392 __ast_pbx_run: Spawn extension (default,5005,6) exited non-zero on 'SIP/testbenchDO-00000004' == Spawn extension (default, 5005, 6) exited non-zero on 'SIP/testbenchDO-00000004' [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: channel.c:2475 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/testbenchDO-00000004' [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: channel.c:2475 ast_softhangup_nolock: Soft-Hanging (0x80) up channel 'SIP/testbenchDO-00000004' [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: pbx.c:2917 pbx_extension_helper: Launching 'Hangup' -- Executing [h@default:1] Hangup("SIP/testbenchDO-00000004", "") in new stack [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: channel.c:2475 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'SIP/testbenchDO-00000004' [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: pbx.c:4204 ast_pbx_h_exten_run: Spawn extension (default,h,1) exited non-zero on 'SIP/testbenchDO-00000004' == Spawn extension (default, h, 1) exited non-zero on 'SIP/testbenchDO-00000004' [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: channel.c:2566 ast_hangup: Channel 0x7fb910030cf8 'SIP/testbenchDO-00000004' hanging up. Refs: 2 [2018-10-18 15:16:59.421] DEBUG[6568]: cdr.c:1463 cdr_object_finalize: Finalized CDR for SIP/testbenchDO-00000004 - start 1539875797.971494 answer 1539875804.011199 end 1539875819.421176 dispo ANSWERED [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: abstract_jb.c:885 hook_destroy_cb: JITTERBUFFER hook destroyed [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: chan_sip.c:7197 sip_hangup: Hangup call SIP/testbenchDO-00000004, SIP callid 7579d02b5dc261dabe8e8e06dc98afba@0:0:0:0:0:0:0:0 [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: channel.c:2211 ast_channel_destructor: Channel 0x7fb910030cf8 'SIP/testbenchDO-00000004' destroying [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: bridge_channel.c:2141 bridge_channel_internal_pull: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: pulling 0x7fb92c022248(SIP/server2-00000005) -- Channel SIP/server2-00000005 left 'simple_bridge' basic-bridge [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: bridge_channel.c:2153 bridge_channel_internal_pull: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: 0x7fb92c022248(SIP/server2-00000005) is leaving simple_bridge technology [2018-10-18 15:16:59.421] DEBUG[6619][C-00000003]: abstract_jb.c:875 datastore_destroy_cb: JITTERBUFFER datastore destroyed [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: bridge.c:1038 smart_bridge_operation: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6 is dissolved, not performing smart bridge operation. [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: res_rtp_asterisk.c:3992 ast_rtp_change_source: Changing ssrc from 1504312612 to 660498 due to a source change [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: channel.c:2566 ast_hangup: Channel 0x7fb92c00ff58 'SIP/server2-00000005' hanging up. Refs: 2 [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: abstract_jb.c:885 hook_destroy_cb: JITTERBUFFER hook destroyed [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: chan_sip.c:7197 sip_hangup: Hangup call SIP/server2-00000005, SIP callid 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 Scheduling destruction of SIP dialog '2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060' in 32000 ms (Method: INVITE) [2018-10-18 15:16:59.421] DEBUG[6559][C-00000003]: bridge.c:677 destroy_bridge: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: actually destroying basic bridge, nobody wants it anymore [2018-10-18 15:16:59.421] DEBUG[6559][C-00000003]: bridge.c:702 destroy_bridge: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: calling basic bridge destructor [2018-10-18 15:16:59.421] DEBUG[6559][C-00000003]: bridge.c:708 destroy_bridge: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: calling simple_bridge technology stop [2018-10-18 15:16:59.421] DEBUG[6559][C-00000003]: bridge.c:715 destroy_bridge: Bridge b43ca019-3ebf-4f70-a69e-5aa69c345cc6: calling simple_bridge technology destructor [2018-10-18 15:16:59.421] DEBUG[6568]: cdr.c:1463 cdr_object_finalize: Finalized CDR for SIP/testbenchDO-00000004 - start 1539875819.421226 answer 1539875819.421226 end 1539875819.421598 dispo ANSWERED [2018-10-18 15:16:59.421] DEBUG[6560]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for SIP - testbenchDO [2018-10-18 15:16:59.421] DEBUG[6560]: chan_sip.c:30587 sip_devicestate: Checking device state for peer testbenchDO [2018-10-18 15:16:59.421] DEBUG[6560]: devicestate.c:466 do_state_change: Changing state for SIP/testbenchDO - state 1 (Not in use) [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: chan_sip.c:12306 reqprep: Strict routing enforced for session 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 Reliably Transmitting (NAT) to 18.184.180.200:5060: BYE sip:5003@18.184.180.200:5060 SIP/2.0 Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK25777ec5;rport Max-Forwards: 70 From: "testbenchDO" ;tag=as7f0f641c To: ;tag=as70a84e8c Call-ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 CSeq: 103 BYE User-Agent: Funbers X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: chan_sip.c:4309 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #7 [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: chan_sip.c:3796 __sip_xmit: Trying to put 'BYE sip:500' onto UDP socket destined for 18.184.180.200:5060 [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: channel.c:2211 ast_channel_destructor: Channel 0x7fb92c00ff58 'SIP/server2-00000005' destroying [2018-10-18 15:16:59.421] DEBUG[6621][C-00000003]: abstract_jb.c:875 datastore_destroy_cb: JITTERBUFFER datastore destroyed [2018-10-18 15:16:59.421] DEBUG[6588]: chan_sip.c:30063 do_stop_session_timer: Session timer stopped: 5 - 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 [2018-10-18 15:16:59.422] DEBUG[6568]: cdr.c:1296 cdr_object_create_public_records: CDR for SIP/server2-00000005 is dialed and has no Party B; discarding [2018-10-18 15:16:59.422] DEBUG[6560]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for SIP - server2 [2018-10-18 15:16:59.422] DEBUG[6560]: chan_sip.c:30587 sip_devicestate: Checking device state for peer server2 [2018-10-18 15:16:59.422] DEBUG[6560]: devicestate.c:466 do_state_change: Changing state for SIP/server2 - state 1 (Not in use) <--- SIP read from UDP:18.184.180.200:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK25777ec5;received=104.248.244.68;rport=5060 From: "testbenchDO" ;tag=as7f0f641c To: ;tag=as70a84e8c Call-ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 CSeq: 103 BYE Server: Funbers Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 <-------------> [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 1 [ 94]: Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK25777ec5;received=104.248.244.68;rport=5060 [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 2 [ 67]: From: "testbenchDO" ;tag=as7f0f641c [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 3 [ 44]: To: ;tag=as70a84e8c [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 4 [ 61]: Call-ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 5 [ 13]: CSeq: 103 BYE [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 6 [ 15]: Server: Funbers [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 7 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 8 [ 26]: Supported: replaces, timer [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:9931 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:9461 __find_call: = Looking for Call ID: 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 (Checking To) --From tag as7f0f641c --To-tag as70a84e8c [2018-10-18 15:16:59.424] DEBUG[6588][C-00000003]: chan_sip.c:4569 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7 [2018-10-18 15:16:59.424] DEBUG[6588][C-00000003]: chan_sip.c:4580 __sip_ack: Stopping retransmission on '2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060' of Request 103: Match Found [2018-10-18 15:16:59.424] DEBUG[6588]: chan_sip.c:6637 sip_pvt_dtor: Destroying SIP dialog 2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060 Really destroying SIP dialog '2424db5b42d1501955ae5f815dd892aa@104.248.244.68:5060' Method: INVITE [2018-10-18 15:16:59.424] DEBUG[6588]: rtp_engine.c:440 instance_destructor: Destroyed RTP instance '0x7fb92c007638'