note: outbound route is through a Cisco PBX (CUCM) but same errors appear in verto-to-verto call (https://pastebin.freeswitch.org/view/e54c7f90) 2020-02-10 19:56:34.418742 [NOTICE] switch_channel.c:1118 New Channel sofia/Localnet/917072057979 [52bba2c4-d387-4770-8e86-4588443efaf3] 2020-02-10 19:56:34.418742 [DEBUG] mod_sofia.c:5096 (sofia/Localnet/917072057979) State Change CS_NEW -> CS_INIT 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:585 (sofia/Localnet/917072057979) Running State Change CS_INIT (Cur 2 Tot 12) 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:628 (sofia/Localnet/917072057979) State INIT 2020-02-10 19:56:34.418742 [DEBUG] mod_sofia.c:93 sofia/Localnet/917072057979 SOFIA INIT 2020-02-10 19:56:34.418742 [DEBUG] sofia_glue.c:1618 sofia/Localnet/917072057979 sending invite version: 1.10.1 -release-12-f9990221e6 64bit Local SDP: v=0 o=FreeSWITCH 1581347046 1581347047 IN IP4 172.20.253.46 s=FreeSWITCH c=IN IP4 172.20.253.46 t=0 0 m=audio 17548 RTP/AVP 0 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 a=sendrecv 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:40 sofia/Localnet/917072057979 Standard INIT 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:48 (sofia/Localnet/917072057979) State Change CS_INIT -> CS_ROUTING 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:628 (sofia/Localnet/917072057979) State INIT going to sleep 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:585 (sofia/Localnet/917072057979) Running State Change CS_ROUTING (Cur 2 Tot 12) 2020-02-10 19:56:34.418742 [DEBUG] sofia.c:7290 Channel sofia/Localnet/917072057979 entering state [calling][0] 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:644 (sofia/Localnet/917072057979) State ROUTING 2020-02-10 19:56:34.418742 [DEBUG] mod_sofia.c:154 sofia/Localnet/917072057979 SOFIA ROUTING 2020-02-10 19:56:34.418742 [DEBUG] switch_ivr_originate.c:67 (sofia/Localnet/917072057979) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:644 (sofia/Localnet/917072057979) State ROUTING going to sleep 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:585 (sofia/Localnet/917072057979) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 12) 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:663 (sofia/Localnet/917072057979) State CONSUME_MEDIA 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:663 (sofia/Localnet/917072057979) State CONSUME_MEDIA going to sleep 2020-02-10 19:56:34.478740 [INFO] sofia.c:1364 sofia/Localnet/917072057979 Update Callee ID to "7072057979" <17072057979> 2020-02-10 19:56:34.478740 [DEBUG] sofia.c:7290 Channel sofia/Localnet/917072057979 entering state [proceeding][183] 2020-02-10 19:56:34.478740 [DEBUG] sofia.c:7300 Remote SDP: v=0 o=CiscoSystemsCCM-SIP 12412155 1 IN IP4 10.0.20.27 s=SIP Call c=IN IP4 10.0.20.27 b=TIAS:64000 b=CT:64 b=AS:64 t=0 0 m=audio 30076 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2020-02-10 19:56:34.478740 [NOTICE] sofia.c:7303 Pre-Answer sofia/Localnet/917072057979! 2020-02-10 19:56:34.478740 [DEBUG] switch_channel.c:3565 (sofia/Localnet/917072057979) Callstate Change DOWN -> EARLY 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:5506 Set telephone-event payload to 101@8000 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:3834 Set Codec sofia/Localnet/917072057979 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2020-02-10 19:56:34.478740 [DEBUG] switch_core_codec.c:111 sofia/Localnet/917072057979 Original read codec set to PCMU:0 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:5849 Set telephone-event payload to 101@8000 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:5907 sofia/Localnet/917072057979 Set 2833 dtmf send payload to 101 recv payload to 101 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:8658 AUDIO RTP [sofia/Localnet/917072057979] 172.20.253.46 port 17548 -> 10.0.20.27 port 30076 codec: 0 ms: 20 2020-02-10 19:56:34.478740 [DEBUG] switch_rtp.c:4408 Starting timer [soft] 160 bytes per 20ms 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:8972 sofia/Localnet/917072057979 Set 2833 dtmf send payload to 101 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:8979 sofia/Localnet/917072057979 Set 2833 dtmf receive payload to 101 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:9002 sofia/Localnet/917072057979 Set rtp dtmf delay to 40 2020-02-10 19:56:34.498742 [DEBUG] switch_ivr_originate.c:436 Setting codec string on verto.rtc/7072057979 to PCMU@8000h@20i 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [opus:111:48000:20:0:2]/[PCMU:0:8000:20:64000:1] 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1] 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1] 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [CN:106:32000:20:0:1]/[PCMU:0:8000:20:64000:1] 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMU:0:8000:20:64000:1] 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5506 Set telephone-event payload to 110@48000 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:3834 Set Codec verto.rtc/7072057979 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2020-02-10 19:56:34.498742 [DEBUG] switch_core_codec.c:111 verto.rtc/7072057979 Original read codec set to PCMU:0 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4279 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.203.1:52162 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4279 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.11.4:52163 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4279 Save audio Candidate cid: 1 proto: udp type: srflx addr: 47.208.143.73:52163 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4324 Searching for rtp candidate. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4333 Choose rtp candidate, index 2, 47.208.143.73:52163 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4099 verto.rtc/7072057979 choosing family v4 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4344 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 47.208.143.73:52163 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4396 setting remote audio ice addr to index 2 47.208.143.73:52163 based on candidate 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4431 Setting remote rtcp audio addr to 47.208.143.73:52163 based on candidate 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5849 Set telephone-event payload to 126@8000 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5907 verto.rtc/7072057979 Set 2833 dtmf send payload to 126 recv payload to 126 2020-02-10 19:56:34.498742 [CRIT] switch_channel.c:1484 Invalid data (${advertised_media_ip} contains a variable) 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:8658 AUDIO RTP [verto.rtc/7072057979] 172.20.253.46 port 31858 -> 47.208.143.73 port 52163 codec: 0 ms: 20 2020-02-10 19:56:34.498742 [CRIT] switch_channel.c:1484 Invalid data (${advertised_media_ip} contains a variable) 2020-02-10 19:56:34.498742 [DEBUG] switch_rtp.c:4408 Starting timer [soft] 160 bytes per 20ms 2020-02-10 19:56:34.498742 [INFO] switch_core_media.c:8840 Activating Audio ICE 2020-02-10 19:56:34.498742 [NOTICE] switch_rtp.c:4910 Activating RTP audio ICE: MEso:E49jHpieyRDYDTvy 47.208.143.73:52163 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:8880 Activating RTCP PORT 52163 2020-02-10 19:56:34.498742 [DEBUG] switch_rtp.c:4806 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 52163 2020-02-10 19:56:34.498742 [INFO] switch_core_media.c:8891 Skipping RTCP ICE (Same as RTP) 2020-02-10 19:56:34.498742 [INFO] switch_rtp.c:3736 Activate RTP/RTCP audio DTLS client 2020-02-10 19:56:34.498742 [INFO] switch_rtp.c:3903 Changing audio DTLS state from OFF to HANDSHAKE 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:2549 Setting Jitterbuffer to 20ms (1 frames) (50 max frames) 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:8972 verto.rtc/7072057979 Set 2833 dtmf send payload to 126 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:8979 verto.rtc/7072057979 Set 2833 dtmf receive payload to 126 2020-02-10 19:56:34.498742 [CRIT] switch_channel.c:1484 Invalid data (${rtp_local_sdp_str} contains a variable) 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:8640 Audio params are unchanged for verto.rtc/7072057979. 2020-02-10 19:56:34.498742 [DEBUG] mod_verto.c:2519 Local SDP verto.rtc/7072057979: v=0 o=FreeSWITCH 1581332736 1581332737 IN IP4 ${external_rtp_ip} s=FreeSWITCH c=IN IP4 ${external_rtp_ip} t=0 0 a=msid-semantic: WMS ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH m=audio 31858 UDP/TLS/RTP/SAVPF 0 126 a=rtpmap:0 PCMU/8000 a=rtpmap:126 telephone-event/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv a=fingerprint:sha-256 96:E9:38:23:96:4C:07:4E:61:4F:80:B7:05:E6:BE:BA:04:CA:F3:69:B6:90:E0:43:59:AD:F1:A9:4B:D1:57:C3 a=setup:active a=rtcp-mux a=rtcp:31858 IN IP4 ${external_rtp_ip} a=ice-ufrag:E49jHpieyRDYDTvy a=ice-pwd:seWjQmYFvVt02UlxPlHnAPrZ a=candidate:9727255544 1 udp 659136 ${external_rtp_ip} 31858 typ host generation 0 a=end-of-candidates a=ssrc:3447296298 cname:5JSy0MzPYj6YEhAu a=ssrc:3447296298 msid:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH a0 a=ssrc:3447296298 mslabel:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH a=ssrc:3447296298 label:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqHa0 2020-02-10 19:56:34.498742 [NOTICE] switch_ivr_originate.c:3755 Pre-Answer verto.rtc/7072057979! 2020-02-10 19:56:34.498742 [DEBUG] switch_channel.c:3565 (verto.rtc/7072057979) Callstate Change RINGING -> EARLY 2020-02-10 19:56:34.498742 [DEBUG] switch_ivr_originate.c:3806 Originate Resulted in Success: [sofia/Localnet/917072057979] 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:12806 verto.rtc/7072057979 PAUSE Jitterbuffer 2020-02-10 19:56:34.498742 [DEBUG] switch_ivr_bridge.c:1794 (sofia/Localnet/917072057979) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2020-02-10 19:56:34.498742 [DEBUG] switch_core_state_machine.c:585 (sofia/Localnet/917072057979) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 12) 2020-02-10 19:56:34.498742 [DEBUG] switch_core_state_machine.c:654 (sofia/Localnet/917072057979) State EXCHANGE_MEDIA 2020-02-10 19:56:34.498742 [DEBUG] mod_sofia.c:663 SOFIA EXCHANGE_MEDIA 2020-02-10 19:56:34.538739 [DEBUG] mod_verto.c:607 WRITE 47.208.143.73:53106 [{ "jsonrpc": "2.0", "id": 12, "method": "verto.media", "params": { "callID": "7088e146-6b2f-2f4b-e970-f12e7a80d7bb", "sdp": "v=0\r\no=FreeSWITCH 1581332736 1581332737 IN IP4 ${external_rtp_ip}\r\ns=FreeSWITCH\r\nc=IN IP4 ${external_rtp_ip}\r\nt=0 0\r\na=msid-semantic: WMS ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH\r\nm=audio 31858 UDP/TLS/RTP/SAVPF 0 126\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:126 telephone-event/8000\r\na=silenceSupp:off - - - -\r\na=ptime:20\r\na=sendrecv\r\na=fingerprint:sha-256 96:E9:38:23:96:4C:07:4E:61:4F:80:B7:05:E6:BE:BA:04:CA:F3:69:B6:90:E0:43:59:AD:F1:A9:4B:D1:57:C3\r\na=setup:active\r\na=rtcp-mux\r\na=rtcp:31858 IN IP4 ${external_rtp_ip}\r\na=ice-ufrag:E49jHpieyRDYDTvy\r\na=ice-pwd:seWjQmYFvVt02UlxPlHnAPrZ\r\na=candidate:9727255544 1 udp 659136 ${external_rtp_ip} 31858 typ host generation 0\r\na=end-of-candidates\r\na=ssrc:3447296298 cname:5JSy0MzPYj6YEhAu\r\na=ssrc:3447296298 msid:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH a0\r\na=ssrc:3447296298 mslabel:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH\r\na=ssrc:3447296298 label:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqHa0\r\n" } }] 2020-02-10 19:56:34.538739 [DEBUG] switch_rtp.c:7720 Correct audio ip/port confirmed. 2020-02-10 19:56:34.618739 [DEBUG] mod_verto.c:1415 READ 47.208.143.73:53106 [{ "jsonrpc": "2.0", "id": 12, "result": { "method": "verto.media" } }] 2020-02-10 19:56:38.438738 [DEBUG] sofia.c:7290 Channel sofia/Localnet/917072057979 entering state [completing][200] 2020-02-10 19:56:38.438738 [DEBUG] sofia.c:7297 Duplicate SDP v=0 o=CiscoSystemsCCM-SIP 12412155 1 IN IP4 10.0.20.27 s=SIP Call c=IN IP4 10.0.20.27 b=TIAS:64000 b=CT:64 b=AS:64 t=0 0 m=audio 30076 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2020-02-10 19:56:38.458740 [DEBUG] sofia.c:7290 Channel sofia/Localnet/917072057979 entering state [ready][200] 2020-02-10 19:56:38.458740 [NOTICE] sofia.c:8409 Channel [sofia/Localnet/917072057979] has been answered