2017-10-10 17:56:54.075303 [NOTICE] mod_logfile.c:192 New log started. c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] mod_rtc.c:392 () State Change CS_NEW -> CS_INIT c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_session.c:641 N/A set UUID=c765070a-5163-d171-46bc-00ba497e7114 c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:486 Looking for zrtp-hash c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:439 Deciding whether to pass zrtp-hash between legs c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:441 CF_ZRTP_PASSTHRU_REQ not set, so not propagating zrtp-hash 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ opus 111 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ ISAC 103 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ ISAC 104 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ G722 9 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ PCMU 0 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ PCMA 8 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ CN 106 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ CN 105 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ CN 13 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ telephone-event 110 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ telephone-event 112 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ telephone-event 113 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ telephone-event 126 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ VP8 96 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ VP9 98 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ H264 100 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ red 102 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ ulpfec 127 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ rtx 97 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ rtx 99 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ rtx 101 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ rtx 125 c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [NOTICE] switch_channel.c:1104 New Channel verto.rtc/91001 [c765070a-5163-d171-46bc-00ba497e7114] c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] mod_verto.c:3761 Remote SDP verto.rtc/91001: c765070a-5163-d171-46bc-00ba497e7114 v=0 c765070a-5163-d171-46bc-00ba497e7114 o=- 7141877043228099558 2 IN IP4 127.0.0.1 c765070a-5163-d171-46bc-00ba497e7114 s=- c765070a-5163-d171-46bc-00ba497e7114 t=0 0 c765070a-5163-d171-46bc-00ba497e7114 a=group:BUNDLE audio video c765070a-5163-d171-46bc-00ba497e7114 a=msid-semantic: WMS 0Jjo0Tgt6livd5JMkJlrPPF2LA87WHm1XpMz c765070a-5163-d171-46bc-00ba497e7114 m=audio 17771 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c765070a-5163-d171-46bc-00ba497e7114 c=IN IP4 166.177.186.163 c765070a-5163-d171-46bc-00ba497e7114 a=rtcp:9 IN IP4 0.0.0.0 c765070a-5163-d171-46bc-00ba497e7114 a=candidate:1004169428 1 udp 2122255103 2001::9d38:6ab8:3ccc:b5e:3f57:69cd 60289 typ host generation 0 network-id 2 network-cost 50 c765070a-5163-d171-46bc-00ba497e7114 a=candidate:236887664 1 udp 2122194687 192.168.150.50 60290 typ host generation 0 network-id 1 c765070a-5163-d171-46bc-00ba497e7114 a=candidate:3264455139 1 udp 1685987071 166.177.186.163 17771 typ srflx raddr 192.168.150.50 rport 60290 generation 0 network-id 1 c765070a-5163-d171-46bc-00ba497e7114 a=candidate:1968804900 1 tcp 1518275327 2001::9d38:6ab8:3ccc:b5e:3f57:69cd 9 typ host tcptype active generation 0 network-id 2 network-cost 50 c765070a-5163-d171-46bc-00ba497e7114 a=candidate:1084056192 1 tcp 1518214911 192.168.150.50 9 typ host tcptype active generation 0 network-id 1 c765070a-5163-d171-46bc-00ba497e7114 a=ice-ufrag:qtzl c765070a-5163-d171-46bc-00ba497e7114 a=ice-pwd:RuCC/5TI0VGIQUOlp767YfnT c765070a-5163-d171-46bc-00ba497e7114 a=ice-options:trickle c765070a-5163-d171-46bc-00ba497e7114 a=fingerprint:sha-256 09:2E:27:6F:C3:5C:3E:01:59:CB:D4:D1:6A:81:53:6C:C9:C2:A0:A1:EF:36:C5:8F:9A:D8:EE:A9:BD:D0:A8:61 c765070a-5163-d171-46bc-00ba497e7114 a=setup:actpass c765070a-5163-d171-46bc-00ba497e7114 a=mid:audio c765070a-5163-d171-46bc-00ba497e7114 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level c765070a-5163-d171-46bc-00ba497e7114 a=sendrecv c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-mux c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:111 opus/48000/2 c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:111 transport-cc c765070a-5163-d171-46bc-00ba497e7114 a=fmtp:111 minptime=10;useinbandfec=1; stereo=1; sprop-stereo=1 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:103 ISAC/16000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:104 ISAC/32000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:9 G722/8000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:0 PCMU/8000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:8 PCMA/8000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:106 CN/32000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:105 CN/16000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:13 CN/8000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:110 telephone-event/48000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:112 telephone-event/32000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:113 telephone-event/16000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:126 telephone-event/8000 c765070a-5163-d171-46bc-00ba497e7114 a=ssrc:542426890 cname:fbu5NeYMSR1+/oqh c765070a-5163-d171-46bc-00ba497e7114 a=ssrc:542426890 msid:0Jjo0Tgt6livd5JMkJlrPPF2LA87WHm1XpMz a4cb3bfd-c0c9-4ade-a919-1e3dec798b7a c765070a-5163-d171-46bc-00ba497e7114 a=ssrc:542426890 mslabel:0Jjo0Tgt6livd5JMkJlrPPF2LA87WHm1XpMz c765070a-5163-d171-46bc-00ba497e7114 a=ssrc:542426890 label:a4cb3bfd-c0c9-4ade-a919-1e3dec798b7a c765070a-5163-d171-46bc-00ba497e7114 m=video 26946 UDP/TLS/RTP/SAVPF 96 98 100 102 127 97 99 101 125 c765070a-5163-d171-46bc-00ba497e7114 c=IN IP4 166.177.186.163 c765070a-5163-d171-46bc-00ba497e7114 a=rtcp:9 IN IP4 0.0.0.0 c765070a-5163-d171-46bc-00ba497e7114 a=candidate:1004169428 1 udp 2122255103 2001::9d38:6ab8:3ccc:b5e:3f57:69cd 60291 typ host generation 0 network-id 2 network-cost 50 c765070a-5163-d171-46bc-00ba497e7114 a=candidate:236887664 1 udp 2122194687 192.168.150.50 60292 typ host generation 0 network-id 1 c765070a-5163-d171-46bc-00ba497e7114 a=candidate:1968804900 1 tcp 1518275327 2001::9d38:6ab8:3ccc:b5e:3f57:69cd 9 typ host tcptype active generation 0 network-id 2 network-cost 50 c765070a-5163-d171-46bc-00ba497e7114 a=candidate:1084056192 1 tcp 1518214911 192.168.150.50 9 typ host tcptype active generation 0 network-id 1 c765070a-5163-d171-46bc-00ba497e7114 a=candidate:3264455139 1 udp 1685987071 166.177.186.163 26946 typ srflx raddr 192.168.150.50 rport 60292 generation 0 network-id 1 c765070a-5163-d171-46bc-00ba497e7114 a=ice-ufrag:qtzl c765070a-5163-d171-46bc-00ba497e7114 a=ice-pwd:RuCC/5TI0VGIQUOlp767YfnT c765070a-5163-d171-46bc-00ba497e7114 a=ice-options:trickle c765070a-5163-d171-46bc-00ba497e7114 a=fingerprint:sha-256 09:2E:27:6F:C3:5C:3E:01:59:CB:D4:D1:6A:81:53:6C:C9:C2:A0:A1:EF:36:C5:8F:9A:D8:EE:A9:BD:D0:A8:61 c765070a-5163-d171-46bc-00ba497e7114 a=setup:actpass c765070a-5163-d171-46bc-00ba497e7114 a=mid:video c765070a-5163-d171-46bc-00ba497e7114 a=extmap:2 urn:ietf:params:rtp-hdrext:toffset c765070a-5163-d171-46bc-00ba497e7114 a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time c765070a-5163-d171-46bc-00ba497e7114 a=extmap:4 urn:3gpp:video-orientation c765070a-5163-d171-46bc-00ba497e7114 a=extmap:5 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 c765070a-5163-d171-46bc-00ba497e7114 a=extmap:6 http://www.webrtc.org/experiments/rtp-hdrext/playout-delay c765070a-5163-d171-46bc-00ba497e7114 a=sendrecv c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-mux c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-rsize c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:96 VP8/90000 c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:96 ccm fir c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:96 nack c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:96 nack pli c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:96 goog-remb c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:96 transport-cc c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:98 VP9/90000 c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:98 ccm fir c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:98 nack c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:98 nack pli c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:98 goog-remb c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:98 transport-cc c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:100 H264/90000 c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:100 ccm fir c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:100 nack c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:100 nack pli c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:100 goog-remb c765070a-5163-d171-46bc-00ba497e7114 a=rtcp-fb:100 transport-cc c765070a-5163-d171-46bc-00ba497e7114 a=fmtp:100 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42e01f c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:102 red/90000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:127 ulpfec/90000 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:97 rtx/90000 c765070a-5163-d171-46bc-00ba497e7114 a=fmtp:97 apt=96 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:99 rtx/90000 c765070a-5163-d171-46bc-00ba497e7114 a=fmtp:99 apt=98 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:101 rtx/90000 c765070a-5163-d171-46bc-00ba497e7114 a=fmtp:101 apt=100 c765070a-5163-d171-46bc-00ba497e7114 a=rtpmap:125 rtx/90000 c765070a-5163-d171-46bc-00ba497e7114 a=fmtp:125 apt=102 c765070a-5163-d171-46bc-00ba497e7114 a=ssrc-group:FID 1147246608 3309211741 c765070a-5163-d171-46bc-00ba497e7114 a=ssrc:1147246608 cname:fbu5NeYMSR1+/oqh c765070a-5163-d171-46bc-00ba497e7114 a=ssrc:1147246608 msid:0Jjo0Tgt6livd5JMkJlrPPF2LA87WHm1XpMz 66367e8f-dee4-40fa-96cc-315b8e0fcd05 c765070a-5163-d171-46bc-00ba497e7114 a=ssrc:1147246608 mslabel:0Jjo0Tgt6livd5JMkJlrPPF2LA87WHm1XpMz c765070a-5163-d171-46bc-00ba497e7114 a=ssrc:1147246608 label:66367e8f-dee4-40fa-96cc-315b8e0fcd05 c765070a-5163-d171-46bc-00ba497e7114 a=ssrc:3309211741 cname:fbu5NeYMSR1+/oqh a=ssrc:3309211741 msid:0Jjo0Tgt6livd5JMkJlrPPF2LA87WHm1XpMz 66367e8f-dee4-40fa-96cc-315b8e0fcd05 a=ssrc:3309211741 mslabel:0Jjo0Tgt6livd5JMkJlrPPF2LA87WHm1XpMz a=ssrc:3309211741 label:66367e8f-dee4-40fa-96cc-315b8e0fcd05 c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/91001) Running State Change CS_INIT (Cur 1 Tot 1) c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:627 (verto.rtc/91001) State INIT c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [ALERT] switch_core_state_machine.c:627 verto.rtc/91001 Send KeyFrame c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:40 verto.rtc/91001 Standard INIT c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:48 (verto.rtc/91001) State Change CS_INIT -> CS_ROUTING c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:627 (verto.rtc/91001) State INIT going to sleep c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/91001) Running State Change CS_ROUTING (Cur 1 Tot 1) c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_channel.c:2249 (verto.rtc/91001) Callstate Change DOWN -> RINGING c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:643 (verto.rtc/91001) State ROUTING c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [ALERT] switch_core_state_machine.c:643 verto.rtc/91001 Send KeyFrame c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] mod_rtc.c:89 verto.rtc/91001 RTC ROUTING c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:236 verto.rtc/91001 Standard ROUTING c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [INFO] mod_dialplan_xml.c:637 Processing 1002 ->91001 in context default c765070a-5163-d171-46bc-00ba497e7114 Dialplan: verto.rtc/91001 parsing [default->baremetal.joshebosh.com] continue=false c765070a-5163-d171-46bc-00ba497e7114 Dialplan: verto.rtc/91001 Regex (PASS) [baremetal.joshebosh.com] ${destination_number}(91001) =~ /^9(10[01][0-9])$/ break=on-false c765070a-5163-d171-46bc-00ba497e7114 Dialplan: verto.rtc/91001 Action bridge(sofia/external/1001@65.15.69.32) c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:286 (verto.rtc/91001) State Change CS_ROUTING -> CS_EXECUTE c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:643 (verto.rtc/91001) State ROUTING going to sleep c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/91001) Running State Change CS_EXECUTE (Cur 1 Tot 1) c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:650 (verto.rtc/91001) State EXECUTE c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [ALERT] switch_core_state_machine.c:650 verto.rtc/91001 Send KeyFrame c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] mod_rtc.c:120 verto.rtc/91001 RTC EXECUTE c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:328 verto.rtc/91001 Standard EXECUTE c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [ALERT] switch_core_session.c:2648 verto.rtc/91001 Send KeyFrame c765070a-5163-d171-46bc-00ba497e7114 EXECUTE verto.rtc/91001 bridge(sofia/external/1001@65.15.69.32) c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [ALERT] switch_core_session.c:2870 verto.rtc/91001 receive message [APPLICATION_EXEC_COMPLETE] c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:02.575303 [DEBUG] switch_ivr_originate.c:2159 Parsing global variables f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [NOTICE] switch_channel.c:1104 New Channel sofia/external/1001@65.15.69.32 [f9c569ed-a077-4ac8-ad50-aaca601e55bd] f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] mod_sofia.c:5026 (sofia/external/1001@65.15.69.32) State Change CS_NEW -> CS_INIT f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1001@65.15.69.32) Running State Change CS_INIT (Cur 2 Tot 2) f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1001@65.15.69.32) State INIT f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [ALERT] switch_core_state_machine.c:627 sofia/external/1001@65.15.69.32 Send KeyFrame f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] mod_sofia.c:93 sofia/external/1001@65.15.69.32 SOFIA INIT 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ opus 102 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ G722 9 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ PCMU 0 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ PCMA 8 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ opus 103 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ VP9 98 2017-10-10 17:57:02.575303 [ALERT] switch_core_media.c:934 ADD PMAP REQ VP8 96 nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] sofia_glue.c:1299 sofia/external/1001@65.15.69.32 sending invite version: 1.9.0 git 542825e 2017-09-24 20:38:29Z 64bit f9c569ed-a077-4ac8-ad50-aaca601e55bd Local SDP: f9c569ed-a077-4ac8-ad50-aaca601e55bd v=0 f9c569ed-a077-4ac8-ad50-aaca601e55bd o=FreeSWITCH 1507641766 1507641767 IN IP4 74.208.165.83 f9c569ed-a077-4ac8-ad50-aaca601e55bd s=FreeSWITCH f9c569ed-a077-4ac8-ad50-aaca601e55bd c=IN IP4 74.208.165.83 f9c569ed-a077-4ac8-ad50-aaca601e55bd t=0 0 f9c569ed-a077-4ac8-ad50-aaca601e55bd m=audio 16456 RTP/AVP 102 9 0 8 103 104 101 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtpmap:102 opus/48000/2 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtpmap:9 G722/8000 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtpmap:0 PCMU/8000 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtpmap:8 PCMA/8000 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtpmap:103 opus/48000/2 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=fmtp:103 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtpmap:104 telephone-event/48000 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=fmtp:104 0-16 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtpmap:101 telephone-event/8000 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=fmtp:101 0-16 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=ptime:20 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=sendrecv f9c569ed-a077-4ac8-ad50-aaca601e55bd m=video 16404 RTP/AVP 98 96 f9c569ed-a077-4ac8-ad50-aaca601e55bd b=AS:1024 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtpmap:98 VP9/90000 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtpmap:96 VP8/90000 f9c569ed-a077-4ac8-ad50-aaca601e55bd a=sendrecv f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtcp-fb:98 ccm fir f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtcp-fb:98 ccm tmmbr f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtcp-fb:98 nack f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtcp-fb:98 nack pli f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtcp-fb:96 ccm fir f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtcp-fb:96 ccm tmmbr f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtcp-fb:96 nack f9c569ed-a077-4ac8-ad50-aaca601e55bd a=rtcp-fb:96 nack pli f9c569ed-a077-4ac8-ad50-aaca601e55bd nua.c:633 nua_invite() nua: nua_invite: entering nua_stack.c:569 nua_stack_signal() nua(0x7fb9f00127f0): recv signal r_invite nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7fb9d8001930, 0x7fb9d8001150, 0x7fb9f00127f0) called soa.c:403 soa_set_params() soa_set_params(static::0x7fb9d80e3720, ...) called soa.c:403 soa_set_params() soa_set_params(static::0x7fb9d80e3720, ...) called soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fb9d80e3720, (nil), 0x7fb9f00214b6, -1) called soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7fb9d80e3720, (nil), 0x7fb9f00214b6, -1) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fb9f00127f0): adding session usage nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fb9d80e9360) soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fb9d80e3720) called soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7fb9d80e3720, 0) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fb9d80e3720, soa_generate_offer): called soa_static.c:1189 offer_answer_step() soa_static(0x7fb9d80e3720, soa_generate_offer): generating local description soa_static.c:1217 offer_answer_step() soa_static(0x7fb9d80e3720, soa_generate_offer): upgrade with local description soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fb9df8b4ac0, (nil), ""): called soa_static.c:1446 offer_answer_step() soa_static(0x7fb9d80e3720, soa_generate_offer): storing local description soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb9d80e3720, [(nil)], [0x7fb9df8b6bf8], [0x7fb9df8b6bf4]) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7fb9d8004640) tpn = */65.15.69.32:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 65.15.69.32:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7fb9d8004640): not found by name */65.15.69.32:5060 tport.c:3594 tport_vsend() tport_vsend(0x7fb9d8004640): 1688 bytes of 1688 to udp/65.15.69.32:5060 tport.c:3492 tport_send_msg() tport_vsend returned 1688 send 1688 bytes to udp/[65.15.69.32]:5060 at 17:57:02.588794: ------------------------------------------------------------------------ INVITE sip:1001@65.15.69.32 SIP/2.0 Via: SIP/2.0/UDP 74.208.165.83:5080;rport;branch=z9hG4bKZrHD3m04cU0QS Max-Forwards: 70 From: "Extension 1002" ;tag=ZcrSy1Ne9F80p To: Call-ID: 42dfb8b3-2887-1236-1aab-0050560f07d6 CSeq: 113493047 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170924T203829Z~542825ef81~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 883 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1002" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1507641766 1507641767 IN IP4 74.208.165.83 s=FreeSWITCH c=IN IP4 74.208.165.83 t=0 0 m=audio 16456 RTP/AVP 102 9 0 8 103 104 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 opus/48000/2 a=fmtp:103 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:104 telephone-event/48000 a=fmtp:104 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 16404 RTP/AVP 98 96 b=AS:1024 a=rtpmap:98 VP9/90000 a=rtpmap:96 VP8/90000 a=rtcp-fb:98 ccm fir a=rtcp-fb:98 ccm tmmbr a=rtcp-fb:98 nack a=rtcp-fb:98 nack pli a=rtcp-fb:96 ccm fir a=rtcp-fb:96 ccm tmmbr a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent INVITE (113493047) to */65.15.69.32:5060 tport.c:4160 tport_pend() tport_pend(0x7fb9d8004640): pending 0x7fb9d80eb510 for udp/74.208.165.83:5080 (already 0) nta.c:1350 set_timeout() nta: timer set to 32000 ms nta.c:1348 set_timeout() nta: timer shortened to 1000 ms nua_session.c:4139 signal_call_state_change() nua(0x7fb9f00127f0): call state changed: init -> calling, sent offer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb9d80e3720, [0x7fb9df8b6bd8], [0x7fb9df8b6be0], [(nil)]) called nua_stack.c:269 nua_stack_event() nua(0x7fb9f00127f0): event i_state INVITE sent nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:529 nua_signal() nua(0x7fb9f00127f0): sent signal r_invite f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:40 sofia/external/1001@65.15.69.32 Standard INIT f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:48 (sofia/external/1001@65.15.69.32) State Change CS_INIT -> CS_ROUTING f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1001@65.15.69.32) State INIT going to sleep f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1001@65.15.69.32) Running State Change CS_ROUTING (Cur 2 Tot 2) nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] sofia.c:7283 Channel sofia/external/1001@65.15.69.32 entering state [calling][0] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1001@65.15.69.32) State ROUTING f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [ALERT] switch_core_state_machine.c:643 sofia/external/1001@65.15.69.32 Send KeyFrame f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] mod_sofia.c:154 sofia/external/1001@65.15.69.32 SOFIA ROUTING f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_ivr_originate.c:67 (sofia/external/1001@65.15.69.32) State Change CS_ROUTING -> CS_CONSUME_MEDIA f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1001@65.15.69.32) State ROUTING going to sleep f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1001@65.15.69.32) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 2) f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:662 (sofia/external/1001@65.15.69.32) State CONSUME_MEDIA f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [ALERT] switch_core_state_machine.c:662 sofia/external/1001@65.15.69.32 Send KeyFrame f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [DEBUG] switch_core_state_machine.c:662 (sofia/external/1001@65.15.69.32) State CONSUME_MEDIA going to sleep f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:02.575303 [ALERT] switch_core_state_machine.c:701 sofia/external/1001@65.15.69.32 session thread sleep state: CS_CONSUME_MEDIA! nta.c:8899 _nta_outgoing_timer() nta: timer A fired, retransmit INVITE (113493047) tport.c:4222 tport_release() tport_release(0x7fb9d8004640): 0x7fb9d80eb510 by 0x7fb9d80ee260 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7fb9d8004640) tpn = */65.15.69.32:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 65.15.69.32:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7fb9d8004640): not found by name */65.15.69.32:5060 tport.c:3594 tport_vsend() tport_vsend(0x7fb9d8004640): 1688 bytes of 1688 to udp/65.15.69.32:5060 tport.c:3492 tport_send_msg() tport_vsend returned 1688 send 1688 bytes to udp/[65.15.69.32]:5060 at 17:57:03.588999: ------------------------------------------------------------------------ INVITE sip:1001@65.15.69.32 SIP/2.0 Via: SIP/2.0/UDP 74.208.165.83:5080;rport;branch=z9hG4bKZrHD3m04cU0QS Max-Forwards: 70 From: "Extension 1002" ;tag=ZcrSy1Ne9F80p To: Call-ID: 42dfb8b3-2887-1236-1aab-0050560f07d6 CSeq: 113493047 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170924T203829Z~542825ef81~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 883 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1002" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1507641766 1507641767 IN IP4 74.208.165.83 s=FreeSWITCH c=IN IP4 74.208.165.83 t=0 0 m=audio 16456 RTP/AVP 102 9 0 8 103 104 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 opus/48000/2 a=fmtp:103 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:104 telephone-event/48000 a=fmtp:104 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 16404 RTP/AVP 98 96 b=AS:1024 a=rtpmap:98 VP9/90000 a=rtpmap:96 VP8/90000 a=rtcp-fb:98 ccm fir a=rtcp-fb:98 ccm tmmbr a=rtcp-fb:98 nack a=rtcp-fb:98 nack pli a=rtcp-fb:96 ccm fir a=rtcp-fb:96 ccm tmmbr a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INVITE (113493047) to */65.15.69.32:5060 tport.c:4160 tport_pend() tport_pend(0x7fb9d8004640): pending 0x7fb9d80eb510 for udp/74.208.165.83:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free nta.c:1296 agent_timer() nta: timer set next to 2000 ms nta.c:8899 _nta_outgoing_timer() nta: timer A fired, retransmit INVITE (113493047) tport.c:4222 tport_release() tport_release(0x7fb9d8004640): 0x7fb9d80eb510 by 0x7fb9d80ee260 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7fb9d8004640) tpn = */65.15.69.32:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 65.15.69.32:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7fb9d8004640): not found by name */65.15.69.32:5060 tport.c:3594 tport_vsend() tport_vsend(0x7fb9d8004640): 1688 bytes of 1688 to udp/65.15.69.32:5060 tport.c:3492 tport_send_msg() tport_vsend returned 1688 send 1688 bytes to udp/[65.15.69.32]:5060 at 17:57:05.588989: ------------------------------------------------------------------------ INVITE sip:1001@65.15.69.32 SIP/2.0 Via: SIP/2.0/UDP 74.208.165.83:5080;rport;branch=z9hG4bKZrHD3m04cU0QS Max-Forwards: 70 From: "Extension 1002" ;tag=ZcrSy1Ne9F80p To: Call-ID: 42dfb8b3-2887-1236-1aab-0050560f07d6 CSeq: 113493047 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170924T203829Z~542825ef81~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 883 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1002" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1507641766 1507641767 IN IP4 74.208.165.83 s=FreeSWITCH c=IN IP4 74.208.165.83 t=0 0 m=audio 16456 RTP/AVP 102 9 0 8 103 104 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 opus/48000/2 a=fmtp:103 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:104 telephone-event/48000 a=fmtp:104 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 16404 RTP/AVP 98 96 b=AS:1024 a=rtpmap:98 VP9/90000 a=rtpmap:96 VP8/90000 a=rtcp-fb:98 ccm fir a=rtcp-fb:98 ccm tmmbr a=rtcp-fb:98 nack a=rtcp-fb:98 nack pli a=rtcp-fb:96 ccm fir a=rtcp-fb:96 ccm tmmbr a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INVITE (113493047) to */65.15.69.32:5060 tport.c:4160 tport_pend() tport_pend(0x7fb9d8004640): pending 0x7fb9d80eb510 for udp/74.208.165.83:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free nta.c:1296 agent_timer() nta: timer set next to 4000 ms nta.c:8899 _nta_outgoing_timer() nta: timer A fired, retransmit INVITE (113493047) tport.c:4222 tport_release() tport_release(0x7fb9d8004640): 0x7fb9d80eb510 by 0x7fb9d80ee260 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7fb9d8004640) tpn = */65.15.69.32:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 65.15.69.32:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7fb9d8004640): not found by name */65.15.69.32:5060 tport.c:3594 tport_vsend() tport_vsend(0x7fb9d8004640): 1688 bytes of 1688 to udp/65.15.69.32:5060 tport.c:3492 tport_send_msg() tport_vsend returned 1688 send 1688 bytes to udp/[65.15.69.32]:5060 at 17:57:09.588990: ------------------------------------------------------------------------ INVITE sip:1001@65.15.69.32 SIP/2.0 Via: SIP/2.0/UDP 74.208.165.83:5080;rport;branch=z9hG4bKZrHD3m04cU0QS Max-Forwards: 70 From: "Extension 1002" ;tag=ZcrSy1Ne9F80p To: Call-ID: 42dfb8b3-2887-1236-1aab-0050560f07d6 CSeq: 113493047 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170924T203829Z~542825ef81~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 883 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1002" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1507641766 1507641767 IN IP4 74.208.165.83 s=FreeSWITCH c=IN IP4 74.208.165.83 t=0 0 m=audio 16456 RTP/AVP 102 9 0 8 103 104 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 opus/48000/2 a=fmtp:103 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:104 telephone-event/48000 a=fmtp:104 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 16404 RTP/AVP 98 96 b=AS:1024 a=rtpmap:98 VP9/90000 a=rtpmap:96 VP8/90000 a=rtcp-fb:98 ccm fir a=rtcp-fb:98 ccm tmmbr a=rtcp-fb:98 nack a=rtcp-fb:98 nack pli a=rtcp-fb:96 ccm fir a=rtcp-fb:96 ccm tmmbr a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INVITE (113493047) to */65.15.69.32:5060 tport.c:4160 tport_pend() tport_pend(0x7fb9d8004640): pending 0x7fb9d80eb510 for udp/74.208.165.83:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free nta.c:1296 agent_timer() nta: timer set next to 8000 ms nta.c:8899 _nta_outgoing_timer() nta: timer A fired, retransmit INVITE (113493047) tport.c:4222 tport_release() tport_release(0x7fb9d8004640): 0x7fb9d80eb510 by 0x7fb9d80ee260 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7fb9d8004640) tpn = */65.15.69.32:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 65.15.69.32:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7fb9d8004640): not found by name */65.15.69.32:5060 tport.c:3594 tport_vsend() tport_vsend(0x7fb9d8004640): 1688 bytes of 1688 to udp/65.15.69.32:5060 tport.c:3492 tport_send_msg() tport_vsend returned 1688 send 1688 bytes to udp/[65.15.69.32]:5060 at 17:57:17.589005: ------------------------------------------------------------------------ INVITE sip:1001@65.15.69.32 SIP/2.0 Via: SIP/2.0/UDP 74.208.165.83:5080;rport;branch=z9hG4bKZrHD3m04cU0QS Max-Forwards: 70 From: "Extension 1002" ;tag=ZcrSy1Ne9F80p To: Call-ID: 42dfb8b3-2887-1236-1aab-0050560f07d6 CSeq: 113493047 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170924T203829Z~542825ef81~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 883 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1002" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1507641766 1507641767 IN IP4 74.208.165.83 s=FreeSWITCH c=IN IP4 74.208.165.83 t=0 0 m=audio 16456 RTP/AVP 102 9 0 8 103 104 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 opus/48000/2 a=fmtp:103 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:104 telephone-event/48000 a=fmtp:104 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 16404 RTP/AVP 98 96 b=AS:1024 a=rtpmap:98 VP9/90000 a=rtpmap:96 VP8/90000 a=rtcp-fb:98 ccm fir a=rtcp-fb:98 ccm tmmbr a=rtcp-fb:98 nack a=rtcp-fb:98 nack pli a=rtcp-fb:96 ccm fir a=rtcp-fb:96 ccm tmmbr a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INVITE (113493047) to */65.15.69.32:5060 tport.c:4160 tport_pend() tport_pend(0x7fb9d8004640): pending 0x7fb9d80eb510 for udp/74.208.165.83:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free nta.c:1296 agent_timer() nta: timer set next to 16000 ms c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.655303 [NOTICE] mod_verto.c:2835 Hangup verto.rtc/91001 [CS_EXECUTE] [NORMAL_CLEARING] f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [NOTICE] switch_ivr_originate.c:3629 Hangup sofia/external/1001@65.15.69.32 [CS_CONSUME_MEDIA] [ORIGINATOR_CANCEL] c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_ivr_originate.c:3854 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [INFO] mod_dptools.c:3508 Originate Failed. Cause: ORIGINATOR_CANCEL c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [ALERT] switch_core_session.c:2885 verto.rtc/91001 receive message [PHONE_EVENT] c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_session.c:2885 verto.rtc/91001 skip receive message [PHONE_EVENT] (channel is hungup already) c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:650 (verto.rtc/91001) State EXECUTE going to sleep c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/91001) Running State Change CS_HANGUP (Cur 2 Tot 2) c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:850 (verto.rtc/91001) Callstate Change RINGING -> HANGUP c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:852 (verto.rtc/91001) State HANGUP c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [ALERT] switch_core_state_machine.c:852 verto.rtc/91001 Send KeyFrame c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:60 verto.rtc/91001 Standard HANGUP, cause: NORMAL_CLEARING c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:852 (verto.rtc/91001) State HANGUP going to sleep c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:619 (verto.rtc/91001) State Change CS_HANGUP -> CS_REPORTING c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/91001) Running State Change CS_REPORTING (Cur 2 Tot 2) c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:938 (verto.rtc/91001) State REPORTING c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [ALERT] switch_core_state_machine.c:938 verto.rtc/91001 Send KeyFrame c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:174 verto.rtc/91001 Standard REPORTING, cause: NORMAL_CLEARING c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:938 (verto.rtc/91001) State REPORTING going to sleep c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:610 (verto.rtc/91001) State Change CS_REPORTING -> CS_DESTROY c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_session.c:1713 Session 1 (verto.rtc/91001) Locked, Waiting on external entities c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [NOTICE] switch_core_session.c:1731 Session 1 (verto.rtc/91001) Ended c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [NOTICE] switch_core_session.c:1735 Close Channel verto.rtc/91001 [CS_DESTROY] c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:741 (verto.rtc/91001) Running State Change CS_DESTROY (Cur 1 Tot 2) c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:751 (verto.rtc/91001) State DESTROY c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [ALERT] switch_core_state_machine.c:751 verto.rtc/91001 Send KeyFrame c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] mod_rtc.c:132 verto.rtc/91001 RTC DESTROY c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:181 verto.rtc/91001 Standard DESTROY c765070a-5163-d171-46bc-00ba497e7114 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:751 (verto.rtc/91001) State DESTROY going to sleep f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [ALERT] switch_core_state_machine.c:705 sofia/external/1001@65.15.69.32 session thread wake state: CS_CONSUME_MEDIA! f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1001@65.15.69.32) Running State Change CS_HANGUP (Cur 1 Tot 2) f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:850 (sofia/external/1001@65.15.69.32) Callstate Change DOWN -> HANGUP f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1001@65.15.69.32) State HANGUP f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [ALERT] switch_core_state_machine.c:852 sofia/external/1001@65.15.69.32 Send KeyFrame f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] mod_sofia.c:449 Channel sofia/external/1001@65.15.69.32 hanging up, cause: ORIGINATOR_CANCEL f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] mod_sofia.c:513 Sending CANCEL to sofia/external/1001@65.15.69.32 nua.c:651 nua_cancel() nua: nua_cancel: entering nua_stack.c:569 nua_stack_signal() nua(0x7fb9f00127f0): recv signal r_cancel nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7fb9d80e3720, ...) called nta.c:8189 outgoing_send_via() nta: delayed sending CANCEL (113493047) nua_stack.c:529 nua_signal() nua(0x7fb9f00127f0): sent signal r_cancel f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:60 sofia/external/1001@65.15.69.32 Standard HANGUP, cause: ORIGINATOR_CANCEL f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1001@65.15.69.32) State HANGUP going to sleep f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:619 (sofia/external/1001@65.15.69.32) State Change CS_HANGUP -> CS_REPORTING f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1001@65.15.69.32) Running State Change CS_REPORTING (Cur 1 Tot 2) f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1001@65.15.69.32) State REPORTING f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [ALERT] switch_core_state_machine.c:938 sofia/external/1001@65.15.69.32 Send KeyFrame f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:174 sofia/external/1001@65.15.69.32 Standard REPORTING, cause: ORIGINATOR_CANCEL f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1001@65.15.69.32) State REPORTING going to sleep f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:610 (sofia/external/1001@65.15.69.32) State Change CS_REPORTING -> CS_DESTROY f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_session.c:1713 Session 2 (sofia/external/1001@65.15.69.32) Locked, Waiting on external entities f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [NOTICE] switch_core_session.c:1731 Session 2 (sofia/external/1001@65.15.69.32) Ended f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [NOTICE] switch_core_session.c:1735 Close Channel sofia/external/1001@65.15.69.32 [CS_DESTROY] f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:741 (sofia/external/1001@65.15.69.32) Running State Change CS_DESTROY (Cur 0 Tot 2) f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1001@65.15.69.32) State DESTROY f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [ALERT] switch_core_state_machine.c:751 sofia/external/1001@65.15.69.32 Send KeyFrame f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] mod_sofia.c:354 sofia/external/1001@65.15.69.32 SOFIA DESTROY f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:181 sofia/external/1001@65.15.69.32 Standard DESTROY f9c569ed-a077-4ac8-ad50-aaca601e55bd 2017-10-10 17:57:32.675303 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1001@65.15.69.32) State DESTROY going to sleep nta.c:8899 _nta_outgoing_timer() nta: timer A fired, retransmit INVITE (113493047) tport.c:4222 tport_release() tport_release(0x7fb9d8004640): 0x7fb9d80eb510 by 0x7fb9d80ee260 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7fb9d8004640) tpn = */65.15.69.32:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 65.15.69.32:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7fb9d8004640): not found by name */65.15.69.32:5060 tport.c:3594 tport_vsend() tport_vsend(0x7fb9d8004640): 1688 bytes of 1688 to udp/65.15.69.32:5060 tport.c:3492 tport_send_msg() tport_vsend returned 1688 send 1688 bytes to udp/[65.15.69.32]:5060 at 17:57:33.588993: ------------------------------------------------------------------------ INVITE sip:1001@65.15.69.32 SIP/2.0 Via: SIP/2.0/UDP 74.208.165.83:5080;rport;branch=z9hG4bKZrHD3m04cU0QS Max-Forwards: 70 From: "Extension 1002" ;tag=ZcrSy1Ne9F80p To: Call-ID: 42dfb8b3-2887-1236-1aab-0050560f07d6 CSeq: 113493047 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170924T203829Z~542825ef81~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 883 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1002" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1507641766 1507641767 IN IP4 74.208.165.83 s=FreeSWITCH c=IN IP4 74.208.165.83 t=0 0 m=audio 16456 RTP/AVP 102 9 0 8 103 104 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 opus/48000/2 a=fmtp:103 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:104 telephone-event/48000 a=fmtp:104 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 16404 RTP/AVP 98 96 b=AS:1024 a=rtpmap:98 VP9/90000 a=rtpmap:96 VP8/90000 a=rtcp-fb:98 ccm fir a=rtcp-fb:98 ccm tmmbr a=rtcp-fb:98 nack a=rtcp-fb:98 nack pli a=rtcp-fb:96 ccm fir a=rtcp-fb:96 ccm tmmbr a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INVITE (113493047) to */65.15.69.32:5060 tport.c:4160 tport_pend() tport_pend(0x7fb9d8004640): pending 0x7fb9d80eb510 for udp/74.208.165.83:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/2 free nta.c:1296 agent_timer() nta: timer set next to 1000 ms nta.c:8988 outgoing_timer_bf() nta: timer B fired, timeout INVITE (113493047) tport.c:4222 tport_release() tport_release(0x7fb9d8004640): 0x7fb9d80eb510 by 0x7fb9d80ee260 with (nil) nua_stack.c:271 nua_stack_event() nua(0x7fb9f00127f0): event r_invite 408 Request Timeout nua_session.c:4139 signal_call_state_change() nua(0x7fb9f00127f0): call state changed: calling -> terminated nua_stack.c:271 nua_stack_event() nua(0x7fb9f00127f0): event i_state 408 Request Timeout nua_stack.c:271 nua_stack_event() nua(0x7fb9f00127f0): event i_terminated 408 Request Timeout nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fb9f00127f0): removing session usage soa.c:356 soa_destroy() soa_destroy(static::0x7fb9d80e3720) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fb9d80e9360) nua_stack.c:271 nua_stack_event() nua(0x7fb9f00127f0): event r_cancel 408 Request Timeout nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/1 resent, 1/1 tout, 0/0 term, 0/2 free nta.c:1296 agent_timer() nta: timer set next to 5000 ms nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:569 nua_stack_signal() nua(0x7fb9f00127f0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) nua_stack.c:529 nua_signal() nua(0x7fb9f00127f0): sent signal r_destroy nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering