benchmark-subject-do*CLI> benchmark-subject-do*CLI> 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: fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 CSeq: 1 INVITE From: "testbenchDO" ;tag=d99221e6 To: Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-37b0e35bd5e7139b2fa609f82da58030 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 5022 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 5024 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:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 0 [ 38]: INVITE sip:5005@104.248.244.68 SIP/2.0 [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 1 [ 57]: Call-ID: fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 2 [ 14]: CSeq: 1 INVITE [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 3 [ 65]: From: "testbenchDO" ;tag=d99221e6 [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 4 [ 29]: To: [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 5 [ 90]: Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-37b0e35bd5e7139b2fa609f82da58030 [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 6 [ 16]: Max-Forwards: 70 [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 7 [104]: Contact: "testbenchDO" [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 8 [ 34]: User-Agent: Jitsi2.10.5550Mac OS X [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 9 [ 29]: Content-Type: application/sdp [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 10 [ 19]: Content-Length: 580 [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 11 [ 0]: [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 0 [ 3]: v=0 [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 1 [ 48]: o=testbenchDO-jitsi.org 0 0 IN IP4 85.24.248.224 [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 2 [ 3]: s=- [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 3 [ 22]: c=IN IP4 85.24.248.224 [2018-10-18 15:41:05.858] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 4 [ 5]: t=0 0 [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 5 [ 24]: m=audio 5022 RTP/AVP 0 8 [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 8 [ 54]: a=extmap:1 urn:ietf:params:rtp-hdrext:csrc-audio-level [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 9 [ 54]: a=extmap:2 urn:ietf:params:rtp-hdrext:ssrc-audio-level [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 10 [ 22]: a=rtcp-xr:voip-metrics [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 11 [ 26]: m=video 5024 RTP/AVP 96 99 [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 12 [ 10]: a=recvonly [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 13 [ 22]: a=rtpmap:96 H264/90000 [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 14 [ 54]: a=fmtp:96 profile-level-id=4DE01f;packetization-mode=1 [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 15 [ 50]: a=imageattr:96 send * recv [x=[1:1920],y=[1:1200]] [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 16 [ 22]: a=rtpmap:99 H264/90000 [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 17 [ 33]: a=fmtp:99 profile-level-id=4DE01f [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9936 parse_request: Body 18 [ 50]: a=imageattr:99 send * recv [x=[1:1920],y=[1:1200]] --- (11 headers 19 lines) --- [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9425 __find_call: = Looking for Call ID: fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 (Checking From) --From tag d99221e6 --To-tag [2018-10-18 15:41:05.859] DEBUG[26638]: acl.c:992 ast_ouraddrfor: For destination '85.24.248.224', our source address is '104.248.244.68'. [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:3907 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 104.248.244.68:5060 [2018-10-18 15:41:05.859] DEBUG[26638]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '85.24.248.224:5060' into... [2018-10-18 15:41:05.859] DEBUG[26638]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '85.24.248.224' and port '5060'. Sending to 85.24.248.224:5060 (NAT) [2018-10-18 15:41:05.859] DEBUG[26638]: chan_sip.c:9012 __sip_alloc: Allocating new SIP dialog for fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 - INVITE (No RTP) [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:28833 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '85.24.248.224:5060' into... [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '85.24.248.224' and port '5060'. Sending to 85.24.248.224:5060 (NAT) [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:26278 handle_request_invite: Initializing initreq for method INVITE - callid fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 Using INVITE request as basis request - fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '104.248.244.68' and port ''. No matching peer for 'testbenchDO' from '85.24.248.224:5060' [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7ff428011210' [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: res_rtp_asterisk.c:3185 ast_rtp_new: Allocated port 56672 for RTP instance '0x7ff428011210' [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7ff428011210' is setup and ready to go [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'benchmark-subject-do' into... [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'benchmark-subject-do' and port ''. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: res_rtp_asterisk.c:5955 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7ff428011210' == Using SIP RTP CoS mark 5 [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:5795 do_setnat: Setting NAT on RTP to On [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10335 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10335 process_sdp: Processing session-level SDP o=testbenchDO-jitsi.org 0 0 IN IP4 85.24.248.224... OK. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10335 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '85.24.248.224' into... [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '85.24.248.224' and port ''. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10335 process_sdp: Processing session-level SDP c=IN IP4 85.24.248.224... OK. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10335 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 0 [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7ff3e0905fb0 Found RTP audio format 8 [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7ff3e0905fb0 Found audio description format PCMU for ID 0 [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 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:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 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:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 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:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (audio) SDP a=rtcp-xr:voip-metrics... UNSUPPORTED OR FAILED. Found RTP video format 96 [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: rtp_engine.c:759 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 96 format for m type on 0x7ff3e0906020 Found RTP video format 99 [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 99 based on m type on 0x7ff3e0906020 [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:33931 process_crypto: Received offer with crypto line for media stream that is not enabled [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (video) SDP a=recvonly... UNSUPPORTED OR FAILED. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:33931 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:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (video) SDP a=rtpmap:96 H264/90000... OK. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:33931 process_crypto: Received offer with crypto line for media stream that is not enabled [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (video) SDP a=fmtp:96 profile-level-id=4DE01f;packetization-mode=1... OK. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:33931 process_crypto: Received offer with crypto line for media stream that is not enabled [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 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:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:33931 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:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (video) SDP a=rtpmap:99 H264/90000... OK. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:33931 process_crypto: Received offer with crypto line for media stream that is not enabled [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (video) SDP a=fmtp:99 profile-level-id=4DE01f... OK. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:33931 process_crypto: Received offer with crypto line for media stream that is not enabled [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (video) SDP a=imageattr:99 send * recv [x=[1:1920],y=[1:1200]]... UNSUPPORTED OR FAILED. 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:41:05.859] DEBUG[26638][C-00000000]: acl.c:992 ast_ouraddrfor: For destination '85.24.248.224', our source address is '104.248.244.68'. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: res_rtp_asterisk.c:6020 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ff428011210' > 0x7ff428016160 -- Strict RTP learning after remote address set to: 85.24.248.224:5022 Peer audio RTP is at port 85.24.248.224:5022 [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7ff428014a38) from 0x7ff3e0905fb0 to 0x7ff4280113d8 [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ff428014a78) from 0x7ff3e0905fb0 to 0x7ff4280113d8 [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: res_rtp_asterisk.c:5854 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7ff428011210' [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:11096 process_sdp: We're settling with these formats: (ulaw|alaw) [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:26410 handle_request_invite: Checking SIP call limits for device [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:6764 update_call_counter: Updating call counter for incoming call [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '104.248.244.68' and port ''. [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: netsock2.c:226 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:41:05.859] DEBUG[26638][C-00000000]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7ff428019990 'SIP/104.248.244.68-00000000' allocated [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:8161 sip_new: *** Our native formats are (ulaw) [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:8162 sip_new: *** Joint capabilities are (ulaw|alaw) [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:8163 sip_new: *** Our capabilities are (opus|silk16|ulaw|alaw) [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:8164 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [2018-10-18 15:41:05.859] DEBUG[26638][C-00000000]: chan_sip.c:8197 sip_new: This channel will not be able to handle video. sip_route_dump: route/path hop: [2018-10-18 15:41:05.860] DEBUG[26638][C-00000000]: chan_sip.c:26615 handle_request_invite: SIP/104.248.244.68-00000000: 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-37b0e35bd5e7139b2fa609f82da58030;received=85.24.248.224;rport=5060 From: "testbenchDO" ;tag=d99221e6 To: Call-ID: fadbd686bcb83bf4490c2ce4ea803823@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:41:05.860] DEBUG[26638][C-00000000]: chan_sip.c:3750 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 85.24.248.224:5060 [2018-10-18 15:41:05.860] DEBUG[26627]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 104.248.244.68 [2018-10-18 15:41:05.860] DEBUG[26627]: chan_sip.c:30371 sip_devicestate: Checking device state for peer 104.248.244.68 [2018-10-18 15:41:05.860] DEBUG[26627]: devicestate.c:474 do_state_change: Changing state for SIP/104.248.244.68 - state 4 (Invalid) [2018-10-18 15:41:05.860] DEBUG[26783][C-00000000]: pbx.c:2877 pbx_extension_helper: Launching 'NoOp' -- Executing [5005@default:1] NoOp("SIP/104.248.244.68-00000000", "============= LOAD TEST ==============") in new stack [2018-10-18 15:41:05.860] DEBUG[26783][C-00000000]: pbx.c:2877 pbx_extension_helper: Launching 'Wait' -- Executing [5005@default:2] Wait("SIP/104.248.244.68-00000000", "2") in new stack [2018-10-18 15:41:07.860] DEBUG[26783][C-00000000]: pbx.c:2877 pbx_extension_helper: Launching 'Progress' -- Executing [5005@default:3] Progress("SIP/104.248.244.68-00000000", "") in new stack [2018-10-18 15:41:07.860] DEBUG[26783][C-00000000]: chan_sip.c:13509 add_sdp: ** Our capability: (ulaw|alaw) Video flag: False Text flag: True [2018-10-18 15:41:07.860] DEBUG[26783][C-00000000]: chan_sip.c:13510 add_sdp: ** Our prefcodec: (nothing) Audio is at 56672 Adding codec ulaw to SDP Adding codec alaw to SDP [2018-10-18 15:41:07.860] DEBUG[26783][C-00000000]: chan_sip.c:13681 add_sdp: -- Done with adding codecs to SDP [2018-10-18 15:41:07.860] DEBUG[26783][C-00000000]: chan_sip.c:13706 add_sdp: Setting framing on incoming call: 20 [2018-10-18 15:41:07.860] DEBUG[26783][C-00000000]: chan_sip.c:13900 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-37b0e35bd5e7139b2fa609f82da58030;received=85.24.248.224;rport=5060 From: "testbenchDO" ;tag=d99221e6 To: ;tag=as713b5e90 Call-ID: fadbd686bcb83bf4490c2ce4ea803823@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: 249 v=0 o=root 1644895613 1644895613 IN IP4 104.248.244.68 s=Asterisk PBX 13.23.1 c=IN IP4 104.248.244.68 t=0 0 m=audio 56672 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:41:07.860] DEBUG[26783][C-00000000]: chan_sip.c:3750 __sip_xmit: Trying to put 'SIP/2.0 183' onto UDP socket destined for 85.24.248.224:5060 [2018-10-18 15:41:07.860] DEBUG[26783][C-00000000]: pbx.c:2877 pbx_extension_helper: Launching 'Wait' -- Executing [5005@default:4] Wait("SIP/104.248.244.68-00000000", "4") in new stack > 0x7ff428016160 -- Strict RTP switching to RTP target address 85.24.248.224:5022 as source [2018-10-18 15:41:09.532] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4784 ast_rtcp_interpret: Got RTCP report of 128 bytes from 85.24.248.224:5023 <--- SIP read from UDP:85.24.248.224:5060 ---> OPTIONS sip:104.248.244.68 SIP/2.0 Call-ID: 33f94fb934ccc55247fa174664a86e46@0:0:0:0:0:0:0:0 CSeq: 64 OPTIONS From: "testbenchDO" ;tag=ecd596a6 To: "testbenchDO" Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-38e4cdd9c59477d5b1da906860563093 Max-Forwards: 70 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:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 0 [ 34]: OPTIONS sip:104.248.244.68 SIP/2.0 [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 1 [ 57]: Call-ID: 33f94fb934ccc55247fa174664a86e46@0:0:0:0:0:0:0:0 [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 2 [ 16]: CSeq: 64 OPTIONS [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 3 [ 65]: From: "testbenchDO" ;tag=ecd596a6 [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 4 [ 50]: To: "testbenchDO" [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 5 [ 90]: Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-38e4cdd9c59477d5b1da906860563093 [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 6 [ 16]: Max-Forwards: 70 [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 7 [104]: Contact: "testbenchDO" [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 8 [ 34]: User-Agent: Jitsi2.10.5550Mac OS X [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 9 [ 79]: Allow: INFO,UPDATE,OPTIONS,MESSAGE,BYE,REFER,SUBSCRIBE,ACK,CANCEL,NOTIFY,INVITE [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 10 [ 61]: Allow-Events: refer,conference,remote-control,message-summary [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 11 [ 17]: Content-Length: 0 --- (12 headers 0 lines) --- [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9425 __find_call: = Looking for Call ID: 33f94fb934ccc55247fa174664a86e46@0:0:0:0:0:0:0:0 (Checking From) --From tag ecd596a6 --To-tag [2018-10-18 15:41:09.854] DEBUG[26638]: acl.c:992 ast_ouraddrfor: For destination '85.24.248.224', our source address is '104.248.244.68'. [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:3907 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 104.248.244.68:5060 [2018-10-18 15:41:09.854] DEBUG[26638]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '85.24.248.224:5060' into... [2018-10-18 15:41:09.854] DEBUG[26638]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '85.24.248.224' and port '5060'. Sending to 85.24.248.224:5060 (NAT) [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:9012 __sip_alloc: Allocating new SIP dialog for 33f94fb934ccc55247fa174664a86e46@0:0:0:0:0:0:0:0 - OPTIONS (No RTP) [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:28833 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [2018-10-18 15:41:09.854] DEBUG[26638]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:41:09.854] DEBUG[26638]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '104.248.244.68' and port ''. [2018-10-18 15:41:09.854] DEBUG[26638]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '104.248.244.68' into... [2018-10-18 15:41:09.854] DEBUG[26638]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '104.248.244.68' and port ''. Looking for s in default (domain 104.248.244.68) <--- Transmitting (NAT) to 85.24.248.224:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-38e4cdd9c59477d5b1da906860563093;received=85.24.248.224;rport=5060 From: "testbenchDO" ;tag=ecd596a6 To: "testbenchDO" ;tag=as5a2e0efb Call-ID: 33f94fb934ccc55247fa174664a86e46@0:0:0:0:0:0:0:0 CSeq: 64 OPTIONS Server: Funbers Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Accept: application/sdp Content-Length: 0 <------------> [2018-10-18 15:41:09.854] DEBUG[26638]: chan_sip.c:3750 __sip_xmit: Trying to put 'SIP/2.0 404' onto UDP socket destined for 85.24.248.224:5060 Scheduling destruction of SIP dialog '33f94fb934ccc55247fa174664a86e46@0:0:0:0:0:0:0:0' in 32000 ms (Method: OPTIONS) > 0x7ff428016160 -- Strict RTP learning complete - Locking on source address 85.24.248.224:5022 [2018-10-18 15:41:11.861] DEBUG[26783][C-00000000]: pbx.c:2877 pbx_extension_helper: Launching 'AGI' -- Executing [5005@default:5] AGI("SIP/104.248.244.68-00000000", "/etc/asterisk/startCall.php") in new stack -- Launched AGI Script /etc/asterisk/startCall.php [2018-10-18 15:41:11.881] DEBUG[26783][C-00000000]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'ANI' is NULL -- AGI Script /etc/asterisk/startCall.php completed, returning 0 [2018-10-18 15:41:11.884] DEBUG[26783][C-00000000]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DSTVAR' is 'server1' [2018-10-18 15:41:11.884] DEBUG[26783][C-00000000]: pbx.c:2877 pbx_extension_helper: Launching 'Dial' -- Executing [5005@default:6] Dial("SIP/104.248.244.68-00000000", "sip/server1/5003") in new stack [2018-10-18 15:41:11.884] DEBUG[26783][C-00000000]: chan_sip.c:30477 sip_request_call: Asked to create a SIP channel with formats: (ulaw) [2018-10-18 15:41:11.884] DEBUG[26783][C-00000000]: chan_sip.c:9012 __sip_alloc: Allocating new SIP dialog for 589168e93a4781345abc5ac11c263e63@127.0.1.1:5060 - INVITE (No RTP) [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7ff408006c30' [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:3185 ast_rtp_new: Allocated port 40436 for RTP instance '0x7ff408006c30' [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7ff408006c30' is setup and ready to go [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'benchmark-subject-do' into... [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'benchmark-subject-do' and port ''. [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:5955 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7ff408006c30' == Using SIP RTP CoS mark 5 [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:5795 do_setnat: Setting NAT on RTP to On [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:3517 obproxy_get: OBPROXY: Not applying OBproxy to this call [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: acl.c:992 ast_ouraddrfor: For destination '35.157.105.234', our source address is '104.248.244.68'. [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:3907 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 104.248.244.68:5060 [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:5795 do_setnat: Setting NAT on RTP to On [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:8797 change_callid_pvt: SIP call-id changed from '589168e93a4781345abc5ac11c263e63@127.0.1.1:5060' to '37400585592deec87fbf4d41307c0398@104.248.244.68:5060' [2018-10-18 15:41:11.885] DEBUG[26616]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7ff40800eab0 'SIP/server1-00000001' allocated [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:8161 sip_new: *** Our native formats are (ulaw) [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:8162 sip_new: *** Joint capabilities are (ulaw) [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:8163 sip_new: *** Our capabilities are (ulaw|alaw) [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:8164 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:8166 sip_new: *** Our preferred formats from the incoming channel are (ulaw) [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:8197 sip_new: This channel will not be able to handle video. [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: channel_internal_api.c:936 ast_channel_callid_set: Channel Call ID changing from [C-00000000] to [C-00000000] [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:6470 sip_call: Outgoing Call for 5003 [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:6764 update_call_counter: Updating call counter for outgoing call [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:13509 add_sdp: ** Our capability: (ulaw|alaw) Video flag: False Text flag: False [2018-10-18 15:41:11.885] DEBUG[26783][C-00000000]: chan_sip.c:13510 add_sdp: ** Our prefcodec: (ulaw) Audio is at 40436 Adding codec ulaw to SDP Adding codec alaw to SDP Adding non-codec 0x1 (telephone-event) to SDP [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:13681 add_sdp: -- Done with adding codecs to SDP [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:13900 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw) [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:3393 initialize_initreq: Initializing initreq for method INVITE - callid 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 0 [ 38]: INVITE sip:5003@35.157.105.234 SIP/2.0 [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK23576403;rport [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 2 [ 16]: Max-Forwards: 70 [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 3 [ 67]: From: "testbenchDO" ;tag=as4386ab55 [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 4 [ 29]: To: [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 5 [ 46]: Contact: [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 6 [ 61]: Call-ID: 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 8 [ 19]: User-Agent: Funbers [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 9 [ 35]: Date: Thu, 18 Oct 2018 15:41:11 GMT [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 10 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 11 [ 26]: Supported: replaces, timer [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:9899 parse_request: Header 12 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 35.157.105.234:5060: INVITE sip:5003@35.157.105.234 SIP/2.0 Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK23576403;rport Max-Forwards: 70 From: "testbenchDO" ;tag=as4386ab55 To: Contact: Call-ID: 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 CSeq: 102 INVITE User-Agent: Funbers Date: Thu, 18 Oct 2018 15:41:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 280 v=0 o=root 1456133570 1456133570 IN IP4 104.248.244.68 s=Asterisk PBX 13.23.1 c=IN IP4 104.248.244.68 t=0 0 m=audio 40436 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:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:4263 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #14 [2018-10-18 15:41:11.886] DEBUG[26783][C-00000000]: chan_sip.c:3750 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 35.157.105.234:5060 -- Called sip/server1/5003 <--- SIP read from UDP:35.157.105.234:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK23576403;received=104.248.244.68;rport=5060 From: "testbenchDO" ;tag=as4386ab55 To: Call-ID: 37400585592deec87fbf4d41307c0398@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:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 1 [ 94]: Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK23576403;received=104.248.244.68;rport=5060 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 2 [ 67]: From: "testbenchDO" ;tag=as4386ab55 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 3 [ 29]: To: [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 4 [ 61]: Call-ID: 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 6 [ 15]: Server: Funbers [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 7 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 8 [ 26]: Supported: replaces, timer [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 9 [ 35]: Session-Expires: 1800;refresher=uas [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 10 [ 39]: Contact: [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 11 [ 17]: Content-Length: 0 --- (12 headers 0 lines) --- [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9425 __find_call: = Looking for Call ID: 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 (Checking To) --From tag as4386ab55 --To-tag [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:4568 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #14 - INVITE (got response) [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:4575 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '37400585592deec87fbf4d41307c0398@104.248.244.68:5060' Request 102: Found [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:23661 handle_response_invite: SIP response 100 to standard invite <--- SIP read from UDP:35.157.105.234:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK23576403;received=104.248.244.68;rport=5060 From: "testbenchDO" ;tag=as4386ab55 To: ;tag=as53e30f88 Call-ID: 37400585592deec87fbf4d41307c0398@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 965434433 965434433 IN IP4 35.157.105.234 s=Asterisk PBX 16.0.0 c=IN IP4 35.157.105.234 t=0 0 m=audio 20422 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:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 1 [ 94]: Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK23576403;received=104.248.244.68;rport=5060 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 2 [ 67]: From: "testbenchDO" ;tag=as4386ab55 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 3 [ 44]: To: ;tag=as53e30f88 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 4 [ 61]: Call-ID: 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 6 [ 15]: Server: Funbers [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 7 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 8 [ 26]: Supported: replaces, timer [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 9 [ 35]: Session-Expires: 1800;refresher=uas [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 10 [ 39]: Contact: [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 11 [ 29]: Content-Type: application/sdp [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 12 [ 14]: Require: timer [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 13 [ 19]: Content-Length: 253 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 14 [ 0]: [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 0 [ 3]: v=0 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 1 [ 48]: o=root 965434433 965434433 IN IP4 35.157.105.234 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 2 [ 21]: s=Asterisk PBX 16.0.0 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 3 [ 23]: c=IN IP4 35.157.105.234 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 4 [ 5]: t=0 0 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 5 [ 27]: m=audio 20422 RTP/AVP 0 101 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 9 [ 10]: a=ptime:20 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9899 parse_request: Body 10 [ 14]: a=maxptime:150 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9936 parse_request: Body 11 [ 10]: a=sendrecv --- (14 headers 12 lines) --- [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:9425 __find_call: = Looking for Call ID: 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 (Checking To) --From tag as4386ab55 --To-tag as53e30f88 [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:4518 __sip_ack: Acked pending invite 102 [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:4534 __sip_ack: Stopping retransmission on '37400585592deec87fbf4d41307c0398@104.248.244.68:5060' of Request 102: Match Found [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:23661 handle_response_invite: SIP response 200 to standard invite [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:10335 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:10335 process_sdp: Processing session-level SDP o=root 965434433 965434433 IN IP4 35.157.105.234... OK. [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:10335 process_sdp: Processing session-level SDP s=Asterisk PBX 16.0.0... UNSUPPORTED OR FAILED. [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '35.157.105.234' into... [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '35.157.105.234' and port ''. [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:10335 process_sdp: Processing session-level SDP c=IN IP4 35.157.105.234... OK. [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:10335 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 0 [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7ff3e0905a70 Found RTP audio format 101 [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7ff3e0905a70 Found audio description format PCMU for ID 0 [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:10798 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:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:10798 process_sdp: Processing media-level (audio) SDP a=maxptime:150... UNSUPPORTED OR FAILED. [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:10798 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:41:11.892] DEBUG[26638][C-00000000]: acl.c:992 ast_ouraddrfor: For destination '35.157.105.234', our source address is '104.248.244.68'. [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: res_rtp_asterisk.c:6020 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ff408006c30' > 0x7ff40800be20 -- Strict RTP learning after remote address set to: 35.157.105.234:20422 Peer audio RTP is at port 35.157.105.234:20422 [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7ff4280213c8) from 0x7ff3e0905a70 to 0x7ff408006df8 [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ff42800c838) from 0x7ff3e0905a70 to 0x7ff408006df8 [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: res_rtp_asterisk.c:5854 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7ff408006c30' [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:11096 process_sdp: We're settling with these formats: (ulaw) [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:11103 process_sdp: We have an owner, now see if we need to change this call [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:11114 process_sdp: Setting native formats after processing SDP. peer joint formats (ulaw), old nativeformats (ulaw) [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:6764 update_call_counter: Updating call counter for outgoing call sip_route_dump: route/path hop: [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:29980 parse_session_expires: Session-Expires: 1800 [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:29996 parse_session_expires: Refresher: UAS [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:12256 reqprep: Strict routing enforced for session 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 Transmitting (NAT) to 35.157.105.234:5060: ACK sip:5003@35.157.105.234:5060 SIP/2.0 Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK77dbf4c2;rport Max-Forwards: 70 From: "testbenchDO" ;tag=as4386ab55 To: ;tag=as53e30f88 Contact: Call-ID: 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 CSeq: 102 ACK User-Agent: Funbers Content-Length: 0 --- [2018-10-18 15:41:11.892] DEBUG[26638][C-00000000]: chan_sip.c:3750 __sip_xmit: Trying to put 'ACK sip:500' onto UDP socket destined for 35.157.105.234:5060 [2018-10-18 15:41:11.892] DEBUG[26638]: chan_sip.c:29907 __start_session_timer: Session timer started: 13 - 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 1768000ms -- SIP/server1-00000001 answered SIP/104.248.244.68-00000000 [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: rtp_engine.c:1516 ast_rtp_instance_early_bridge: Setting early bridge SDP of 'SIP/104.248.244.68-00000000' with that of 'SIP/server1-00000001' [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: chan_sip.c:7409 sip_answer: SIP answering channel: SIP/104.248.244.68-00000000 [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:3587 ast_rtp_update_source: Setting the marker bit due to a source update [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: chan_sip.c:13509 add_sdp: ** Our capability: (ulaw|alaw) Video flag: False Text flag: True [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: chan_sip.c:13510 add_sdp: ** Our prefcodec: (nothing) Audio is at 56672 Adding codec ulaw to SDP Adding codec alaw to SDP [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: chan_sip.c:13681 add_sdp: -- Done with adding codecs to SDP [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: chan_sip.c:13706 add_sdp: Setting framing on incoming call: 20 [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: chan_sip.c:13900 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-37b0e35bd5e7139b2fa609f82da58030;received=85.24.248.224;rport=5060 From: "testbenchDO" ;tag=d99221e6 To: ;tag=as713b5e90 Call-ID: fadbd686bcb83bf4490c2ce4ea803823@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: 249 v=0 o=root 1644895613 1644895613 IN IP4 104.248.244.68 s=Asterisk PBX 13.23.1 c=IN IP4 104.248.244.68 t=0 0 m=audio 56672 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:41:11.893] DEBUG[26783][C-00000000]: chan_sip.c:4263 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3 [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: chan_sip.c:3750 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 85.24.248.224:5060 [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: bridge.c:502 find_best_technology: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: bridge_native_rtp.c:736 native_rtp_bridge_compatible: Bridge '7badddbf-5f38-4101-8729-b33b5bd22158' can not use native RTP bridge as two channels are required [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: bridge.c:795 bridge_base_init: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: calling simple_bridge technology constructor [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: bridge.c:803 bridge_base_init: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: calling simple_bridge technology start [2018-10-18 15:41:11.893] DEBUG[26627]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - server1 [2018-10-18 15:41:11.893] DEBUG[26627]: chan_sip.c:30371 sip_devicestate: Checking device state for peer server1 [2018-10-18 15:41:11.893] DEBUG[26627]: devicestate.c:474 do_state_change: Changing state for SIP/server1 - state 1 (Not in use) [2018-10-18 15:41:11.893] DEBUG[26627]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 104.248.244.68 [2018-10-18 15:41:11.893] DEBUG[26627]: chan_sip.c:30371 sip_devicestate: Checking device state for peer 104.248.244.68 [2018-10-18 15:41:11.893] DEBUG[26627]: devicestate.c:474 do_state_change: Changing state for SIP/104.248.244.68 - state 4 (Invalid) [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge_channel.c:2686 bridge_channel_internal_join: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: 0x7ff408022d90(SIP/server1-00000001) is joining [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge_channel.c:2148 bridge_channel_internal_push_full: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: pushing 0x7ff408022d90(SIP/server1-00000001) -- Channel SIP/server1-00000001 joined 'simple_bridge' basic-bridge <7badddbf-5f38-4101-8729-b33b5bd22158> [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge_native_rtp.c:736 native_rtp_bridge_compatible: Bridge '7badddbf-5f38-4101-8729-b33b5bd22158' can not use native RTP bridge as two channels are required [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge.c:1047 smart_bridge_operation: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158 is already using the new technology. [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge.c:432 bridge_channel_complete_join: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: 0x7ff408022d90(SIP/server1-00000001) is joining simple_bridge technology [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:3601 ast_rtp_change_source: Not changing SSRC since we haven't sent any RTP yet [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge_native_rtp.c:736 native_rtp_bridge_compatible: Bridge '7badddbf-5f38-4101-8729-b33b5bd22158' can not use native RTP bridge as two channels are required [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [2018-10-18 15:41:11.893] DEBUG[26786][C-00000000]: bridge.c:1047 smart_bridge_operation: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158 is already using the new technology. [2018-10-18 15:41:11.893] DEBUG[26783][C-00000000]: bridge_channel.c:2686 bridge_channel_internal_join: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: 0x7ff408012c60(SIP/104.248.244.68-00000000) is joining [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge_channel.c:2148 bridge_channel_internal_push_full: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: pushing 0x7ff408012c60(SIP/104.248.244.68-00000000) -- Channel SIP/104.248.244.68-00000000 joined 'simple_bridge' basic-bridge <7badddbf-5f38-4101-8729-b33b5bd22158> [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge_native_rtp.c:626 native_rtp_bridge_compatible_check: Bridge '7badddbf-5f38-4101-8729-b33b5bd22158'. Checking compatability for channels 'SIP/server1-00000001' and 'SIP/104.248.244.68-00000000' [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge_native_rtp.c:630 native_rtp_bridge_compatible_check: Bridge '7badddbf-5f38-4101-8729-b33b5bd22158' can not use native RTP bridge as channel 'SIP/server1-00000001' has features which prevent it [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge.c:1047 smart_bridge_operation: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158 is already using the new technology. [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge.c:432 bridge_channel_complete_join: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: 0x7ff408012c60(SIP/104.248.244.68-00000000) is joining simple_bridge technology [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:3601 ast_rtp_change_source: Not changing SSRC since we haven't sent any RTP yet [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge_native_rtp.c:626 native_rtp_bridge_compatible_check: Bridge '7badddbf-5f38-4101-8729-b33b5bd22158'. Checking compatability for channels 'SIP/server1-00000001' and 'SIP/104.248.244.68-00000000' [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge_native_rtp.c:630 native_rtp_bridge_compatible_check: Bridge '7badddbf-5f38-4101-8729-b33b5bd22158' can not use native RTP bridge as channel 'SIP/server1-00000001' has features which prevent it [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [2018-10-18 15:41:11.894] DEBUG[26783][C-00000000]: bridge.c:1047 smart_bridge_operation: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158 is already using the new technology. [2018-10-18 15:41:11.894] DEBUG[26628]: cdr.c:1462 cdr_object_finalize: Finalized CDR for SIP/server1-00000001 - start 1539877271.885432 answer 1539877271.893621 end 1539877271.894250 dispo ANSWERED [2018-10-18 15:41:11.894] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4177 ast_rtp_write: Ooh, format changed from none to ulaw [2018-10-18 15:41:11.894] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4017 rtp_raw_write: Starting RTCP transmission on RTP instance '0x7ff408006c30' <--- SIP read from UDP:85.24.248.224:5060 ---> ACK sip:5005@104.248.244.68:5060 SIP/2.0 Call-ID: fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 CSeq: 1 ACK Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-e8d5e41a4a79bba7be09d66c02beb01a From: "testbenchDO" ;tag=d99221e6 To: ;tag=as713b5e90 Max-Forwards: 70 Contact: "testbenchDO" User-Agent: Jitsi2.10.5550Mac OS X Content-Length: 0 <-------------> [2018-10-18 15:41:11.925] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 0 [ 40]: ACK sip:5005@104.248.244.68:5060 SIP/2.0 [2018-10-18 15:41:11.925] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 1 [ 57]: Call-ID: fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 [2018-10-18 15:41:11.925] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 2 [ 11]: CSeq: 1 ACK [2018-10-18 15:41:11.925] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 3 [ 90]: Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-e8d5e41a4a79bba7be09d66c02beb01a [2018-10-18 15:41:11.925] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 4 [ 65]: From: "testbenchDO" ;tag=d99221e6 [2018-10-18 15:41:11.925] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 5 [ 44]: To: ;tag=as713b5e90 [2018-10-18 15:41:11.925] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 6 [ 16]: Max-Forwards: 70 [2018-10-18 15:41:11.925] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 7 [104]: Contact: "testbenchDO" [2018-10-18 15:41:11.925] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 8 [ 34]: User-Agent: Jitsi2.10.5550Mac OS X [2018-10-18 15:41:11.925] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [2018-10-18 15:41:11.925] DEBUG[26638]: chan_sip.c:9425 __find_call: = Looking for Call ID: fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 (Checking From) --From tag d99221e6 --To-tag as713b5e90 [2018-10-18 15:41:11.925] DEBUG[26638][C-00000000]: chan_sip.c:28833 handle_incoming: **** Received ACK (6) - Command in SIP ACK [2018-10-18 15:41:11.925] DEBUG[26638][C-00000000]: chan_sip.c:4523 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3 [2018-10-18 15:41:11.925] DEBUG[26638][C-00000000]: chan_sip.c:4534 __sip_ack: Stopping retransmission on 'fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0' of Response 1: Match Found [2018-10-18 15:41:11.959] WARNING[26783][C-00000000]: chan_iax2.c:1240 jb_warning_output: Resyncing the jb. last_delay 0, this delay -3835, threshold 1000, new offset 3835 [2018-10-18 15:41:12.084] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:12.170] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4784 ast_rtcp_interpret: Got RTCP report of 80 bytes from 85.24.248.224:5023 [2018-10-18 15:41:12.314] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:12.783] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame > 0x7ff40800be20 -- Strict RTP switching to RTP target address 35.157.105.234:20422 as source [2018-10-18 15:41:12.917] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4177 ast_rtp_write: Ooh, format changed from none to ulaw [2018-10-18 15:41:12.976] WARNING[26786][C-00000000]: chan_iax2.c:1240 jb_warning_output: Resyncing the jb. last_delay 0, this delay 1002, threshold 1000, new offset -1002 [2018-10-18 15:41:12.999] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:13.423] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:13.534] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:13.966] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:14.054] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:14.573] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:14.584] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:15.093] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:15.125] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:15.613] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:15.787] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:16.133] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:16.328] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:16.653] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:16.848] DEBUG[26638]: chan_sip.c:4358 __sip_autodestruct: Auto destroying SIP dialog 'eaf0ab27beea935f3d4fbd94fbdc7958@0:0:0:0:0:0:0:0' [2018-10-18 15:41:16.849] DEBUG[26638]: chan_sip.c:6586 sip_pvt_dtor: Destroying SIP dialog eaf0ab27beea935f3d4fbd94fbdc7958@0:0:0:0:0:0:0:0 Really destroying SIP dialog 'eaf0ab27beea935f3d4fbd94fbdc7958@0:0:0:0:0:0:0:0' Method: OPTIONS [2018-10-18 15:41:16.895] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4784 ast_rtcp_interpret: Got RTCP report of 100 bytes from 35.157.105.234:20423 > 0x7ff40800be20 -- Strict RTP learning complete - Locking on source address 35.157.105.234:20422 [2018-10-18 15:41:16.968] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:17.153] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4784 ast_rtcp_interpret: Got RTCP report of 104 bytes from 85.24.248.224:5023 [2018-10-18 15:41:17.173] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:17.314] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:17.543] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:17.693] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:18.085] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:18.213] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:18.682] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:18.733] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:19.204] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:19.253] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:19.674] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:19.725] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:19.773] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:20.293] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:20.331] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:20.813] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:20.858] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4784 ast_rtcp_interpret: Got RTCP report of 152 bytes from 85.24.248.224:5023 [2018-10-18 15:41:20.884] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:21.333] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:21.472] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:21.853] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:21.894] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4784 ast_rtcp_interpret: Got RTCP report of 100 bytes from 35.157.105.234:20423 [2018-10-18 15:41:21.991] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:22.334] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:22.373] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:22.534] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:22.554] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:22.590] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:22.893] DEBUG[26783][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff428011210' so dropping frame [2018-10-18 15:41:23.034] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:23.054] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' so dropping frame [2018-10-18 15:41:23.067] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:4141 ast_rtp_write: Received frame with no data for RTP instance '0x7ff408006c30' 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=d99221e6 To: ;tag=as713b5e90 Call-ID: fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 Max-Forwards: 70 Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-d2b9fce89d805312f5e9a7d1b4824a4c Contact: "testbenchDO" User-Agent: Jitsi2.10.5550Mac OS X Content-Length: 0 <-------------> [2018-10-18 15:41:23.319] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 0 [ 40]: BYE sip:5005@104.248.244.68:5060 SIP/2.0 [2018-10-18 15:41:23.319] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 1 [ 11]: CSeq: 2 BYE [2018-10-18 15:41:23.319] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 2 [ 65]: From: "testbenchDO" ;tag=d99221e6 [2018-10-18 15:41:23.319] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 3 [ 44]: To: ;tag=as713b5e90 [2018-10-18 15:41:23.319] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 4 [ 57]: Call-ID: fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 [2018-10-18 15:41:23.319] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 5 [ 16]: Max-Forwards: 70 [2018-10-18 15:41:23.319] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 6 [ 90]: Via: SIP/2.0/UDP 85.24.248.224:5060;branch=z9hG4bK-353033-d2b9fce89d805312f5e9a7d1b4824a4c [2018-10-18 15:41:23.319] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 7 [104]: Contact: "testbenchDO" [2018-10-18 15:41:23.319] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 8 [ 34]: User-Agent: Jitsi2.10.5550Mac OS X [2018-10-18 15:41:23.319] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [2018-10-18 15:41:23.319] DEBUG[26638]: chan_sip.c:9425 __find_call: = Looking for Call ID: fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 (Checking From) --From tag d99221e6 --To-tag as713b5e90 [2018-10-18 15:41:23.319] DEBUG[26638][C-00000000]: chan_sip.c:28833 handle_incoming: **** Received BYE (8) - Command in SIP BYE [2018-10-18 15:41:23.319] DEBUG[26638][C-00000000]: chan_sip.c:27271 handle_request_bye: Initializing initreq for method BYE - callid fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 [2018-10-18 15:41:23.319] DEBUG[26638][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '85.24.248.224:5060' into... [2018-10-18 15:41:23.319] DEBUG[26638][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '85.24.248.224' and port '5060'. Sending to 85.24.248.224:5060 (NAT) [2018-10-18 15:41:23.319] DEBUG[26638][C-00000000]: chan_sip.c:3406 sip_alreadygone: Setting SIP_ALREADYGONE on dialog fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 Scheduling destruction of SIP dialog 'fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0' in 32000 ms (Method: BYE) [2018-10-18 15:41:23.319] DEBUG[26638][C-00000000]: chan_sip.c:27434 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-d2b9fce89d805312f5e9a7d1b4824a4c;received=85.24.248.224;rport=5060 From: "testbenchDO" ;tag=d99221e6 To: ;tag=as713b5e90 Call-ID: fadbd686bcb83bf4490c2ce4ea803823@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:41:23.319] DEBUG[26638][C-00000000]: chan_sip.c:3750 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 85.24.248.224:5060 [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: bridge_channel.c:290 ast_bridge_channel_leave_bridge_nolock: Setting 0x7ff408012c60(SIP/104.248.244.68-00000000) state from:0 to:1 [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: bridge_channel.c:2085 bridge_channel_internal_pull: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: pulling 0x7ff408012c60(SIP/104.248.244.68-00000000) -- Channel SIP/104.248.244.68-00000000 left 'simple_bridge' basic-bridge <7badddbf-5f38-4101-8729-b33b5bd22158> [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: bridge_channel.c:2097 bridge_channel_internal_pull: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: 0x7ff408012c60(SIP/104.248.244.68-00000000) is leaving simple_bridge technology [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: bridge.c:322 bridge_dissolve: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: dissolving bridge with cause 16(Normal Clearing) [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: bridge_channel.c:290 ast_bridge_channel_leave_bridge_nolock: Setting 0x7ff408022d90(SIP/server1-00000001) state from:0 to:2 [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: bridge.c:283 bridge_queue_action_nodup: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: queueing action type:13 sub:1001 [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: bridge.c:1004 smart_bridge_operation: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158 is dissolved, not performing smart bridge operation. [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: app_dial.c:3235 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: pbx.c:4349 __ast_pbx_run: Spawn extension (default,5005,6) exited non-zero on 'SIP/104.248.244.68-00000000' == Spawn extension (default, 5005, 6) exited non-zero on 'SIP/104.248.244.68-00000000' [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: channel.c:2592 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/104.248.244.68-00000000' [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: channel.c:2592 ast_softhangup_nolock: Soft-Hanging (0x80) up channel 'SIP/104.248.244.68-00000000' [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: pbx.c:2877 pbx_extension_helper: Launching 'Hangup' -- Executing [h@default:1] Hangup("SIP/104.248.244.68-00000000", "") in new stack [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: channel.c:2592 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'SIP/104.248.244.68-00000000' [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: pbx.c:4158 ast_pbx_h_exten_run: Spawn extension (default,h,1) exited non-zero on 'SIP/104.248.244.68-00000000' [2018-10-18 15:41:23.320] DEBUG[26628]: cdr.c:1462 cdr_object_finalize: Finalized CDR for SIP/104.248.244.68-00000000 - start 1539877265.860241 answer 1539877271.893641 end 1539877283.320354 dispo ANSWERED == Spawn extension (default, h, 1) exited non-zero on 'SIP/104.248.244.68-00000000' [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: channel.c:2683 ast_hangup: Channel 0x7ff428019990 'SIP/104.248.244.68-00000000' hanging up. Refs: 2 [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: abstract_jb.c:887 hook_destroy_cb: JITTERBUFFER hook destroyed [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: chan_sip.c:7151 sip_hangup: Hangup call SIP/104.248.244.68-00000000, SIP callid fadbd686bcb83bf4490c2ce4ea803823@0:0:0:0:0:0:0:0 [2018-10-18 15:41:23.320] DEBUG[26786][C-00000000]: bridge_channel.c:2085 bridge_channel_internal_pull: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: pulling 0x7ff408022d90(SIP/server1-00000001) [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: channel.c:2235 ast_channel_destructor: Channel 0x7ff428019990 'SIP/104.248.244.68-00000000' destroying -- Channel SIP/server1-00000001 left 'simple_bridge' basic-bridge <7badddbf-5f38-4101-8729-b33b5bd22158> [2018-10-18 15:41:23.320] DEBUG[26786][C-00000000]: bridge_channel.c:2097 bridge_channel_internal_pull: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: 0x7ff408022d90(SIP/server1-00000001) is leaving simple_bridge technology [2018-10-18 15:41:23.320] DEBUG[26783][C-00000000]: abstract_jb.c:877 datastore_destroy_cb: JITTERBUFFER datastore destroyed [2018-10-18 15:41:23.320] DEBUG[26628]: cdr.c:1462 cdr_object_finalize: Finalized CDR for SIP/104.248.244.68-00000000 - start 1539877283.320389 answer 1539877283.320389 end 1539877283.320580 dispo ANSWERED [2018-10-18 15:41:23.320] DEBUG[26786][C-00000000]: bridge.c:1004 smart_bridge_operation: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158 is dissolved, not performing smart bridge operation. [2018-10-18 15:41:23.320] DEBUG[26786][C-00000000]: res_rtp_asterisk.c:3608 ast_rtp_change_source: Changing ssrc from 802559851 to 243328382 due to a source change [2018-10-18 15:41:23.320] DEBUG[26786][C-00000000]: channel.c:2683 ast_hangup: Channel 0x7ff40800eab0 'SIP/server1-00000001' hanging up. Refs: 2 [2018-10-18 15:41:23.320] DEBUG[26786][C-00000000]: abstract_jb.c:887 hook_destroy_cb: JITTERBUFFER hook destroyed [2018-10-18 15:41:23.320] DEBUG[26786][C-00000000]: chan_sip.c:7151 sip_hangup: Hangup call SIP/server1-00000001, SIP callid 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 Scheduling destruction of SIP dialog '37400585592deec87fbf4d41307c0398@104.248.244.68:5060' in 32000 ms (Method: INVITE) [2018-10-18 15:41:23.320] DEBUG[26786][C-00000000]: chan_sip.c:12256 reqprep: Strict routing enforced for session 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 [2018-10-18 15:41:23.321] DEBUG[26627]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 104.248.244.68 [2018-10-18 15:41:23.321] DEBUG[26627]: chan_sip.c:30371 sip_devicestate: Checking device state for peer 104.248.244.68 [2018-10-18 15:41:23.321] DEBUG[26627]: devicestate.c:474 do_state_change: Changing state for SIP/104.248.244.68 - state 4 (Invalid) Reliably Transmitting (NAT) to 35.157.105.234:5060: BYE sip:5003@35.157.105.234:5060 SIP/2.0 Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK710adb51;rport Max-Forwards: 70 From: "testbenchDO" ;tag=as4386ab55 To: ;tag=as53e30f88 Call-ID: 37400585592deec87fbf4d41307c0398@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:41:23.321] DEBUG[26786][C-00000000]: chan_sip.c:4263 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3 [2018-10-18 15:41:23.321] DEBUG[26786][C-00000000]: chan_sip.c:3750 __sip_xmit: Trying to put 'BYE sip:500' onto UDP socket destined for 35.157.105.234:5060 [2018-10-18 15:41:23.321] DEBUG[26786][C-00000000]: channel.c:2235 ast_channel_destructor: Channel 0x7ff40800eab0 'SIP/server1-00000001' destroying [2018-10-18 15:41:23.321] DEBUG[26786][C-00000000]: abstract_jb.c:877 datastore_destroy_cb: JITTERBUFFER datastore destroyed [2018-10-18 15:41:23.321] DEBUG[26628]: cdr.c:1295 cdr_object_create_public_records: CDR for SIP/server1-00000001 is dialed and has no Party B; discarding [2018-10-18 15:41:23.321] DEBUG[26627]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - server1 [2018-10-18 15:41:23.321] DEBUG[26627]: chan_sip.c:30371 sip_devicestate: Checking device state for peer server1 [2018-10-18 15:41:23.321] DEBUG[26626][C-00000000]: bridge.c:649 destroy_bridge: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: actually destroying basic bridge, nobody wants it anymore [2018-10-18 15:41:23.321] DEBUG[26627]: devicestate.c:474 do_state_change: Changing state for SIP/server1 - state 1 (Not in use) [2018-10-18 15:41:23.321] DEBUG[26626][C-00000000]: bridge.c:674 destroy_bridge: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: calling basic bridge destructor [2018-10-18 15:41:23.321] DEBUG[26626][C-00000000]: bridge.c:680 destroy_bridge: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: calling simple_bridge technology stop [2018-10-18 15:41:23.321] DEBUG[26626][C-00000000]: bridge.c:687 destroy_bridge: Bridge 7badddbf-5f38-4101-8729-b33b5bd22158: calling simple_bridge technology destructor [2018-10-18 15:41:23.321] DEBUG[26638]: chan_sip.c:29846 do_stop_session_timer: Session timer stopped: 13 - 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 <--- SIP read from UDP:35.157.105.234:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK710adb51;received=104.248.244.68;rport=5060 From: "testbenchDO" ;tag=as4386ab55 To: ;tag=as53e30f88 Call-ID: 37400585592deec87fbf4d41307c0398@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:41:23.322] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [2018-10-18 15:41:23.322] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 1 [ 94]: Via: SIP/2.0/UDP 104.248.244.68:5060;branch=z9hG4bK710adb51;received=104.248.244.68;rport=5060 [2018-10-18 15:41:23.322] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 2 [ 67]: From: "testbenchDO" ;tag=as4386ab55 [2018-10-18 15:41:23.322] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 3 [ 44]: To: ;tag=as53e30f88 [2018-10-18 15:41:23.322] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 4 [ 61]: Call-ID: 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 [2018-10-18 15:41:23.322] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 5 [ 13]: CSeq: 103 BYE [2018-10-18 15:41:23.322] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 6 [ 15]: Server: Funbers [2018-10-18 15:41:23.322] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 7 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [2018-10-18 15:41:23.322] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 8 [ 26]: Supported: replaces, timer [2018-10-18 15:41:23.322] DEBUG[26638]: chan_sip.c:9899 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [2018-10-18 15:41:23.322] DEBUG[26638]: chan_sip.c:9425 __find_call: = Looking for Call ID: 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 (Checking To) --From tag as4386ab55 --To-tag as53e30f88 [2018-10-18 15:41:23.322] DEBUG[26638][C-00000000]: chan_sip.c:4523 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3 [2018-10-18 15:41:23.322] DEBUG[26638][C-00000000]: chan_sip.c:4534 __sip_ack: Stopping retransmission on '37400585592deec87fbf4d41307c0398@104.248.244.68:5060' of Request 103: Match Found [2018-10-18 15:41:23.322] DEBUG[26638]: chan_sip.c:6586 sip_pvt_dtor: Destroying SIP dialog 37400585592deec87fbf4d41307c0398@104.248.244.68:5060 Really destroying SIP dialog '37400585592deec87fbf4d41307c0398@104.248.244.68:5060' Method: INVITE [2018-10-18 15:41:23.322] DEBUG[26638]: rtp_engine.c:402 instance_destructor: Destroyed RTP instance '0x7ff408006c30' benchmark-subject-do*CLI> benchmark-subject-do*CLI> benchmark-subject-do*CLI> benchmark-subject-do*CLI> benchmark-subject-do*CLI>