Skip to content

AUDIO RTP REPORTS ERROR: [Remote Address Error!] when start call by WebRtc and jsSip (error only on Freeswitch build from source code) #1147

New issue
New issue
Closed
Closed
AUDIO RTP REPORTS ERROR: [Remote Address Error!] when start call by WebRtc and jsSip (error only on Freeswitch build from source code)#1147
Labels
bugSomething isn't working
@gaki4

Description

@gaki4
gaki4
opened on Apr 6, 2021

Hello everyone.
I catch error when tried to make a call via WebRTC.
Please tell me what could be the problem.

I use Chrome and JsSip library version 3.4.4
Server operation system is Centos 7

If make call with Freeswitch installed from repo (version 1.10.4), all work good, but if i make call with Freeswitch installed from source code (tried versions: 1.10.4 , 1.10.5 , 1.10.6) i catch this error:
AUDIO RTP REPORTS ERROR: [Remote Address Error!]

When i read logs, i noticed one different between repo installed freeswitch and freeswitch installed from source code. After this difference a catch error on Freeswitch installed from source code.

Freeswitch from repo:
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:4338 Choose rtp candidate, index 1, my_wan_ip:55731

Freeswitch from source code:
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:4349 Choose rtp candidate, index 0, 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local:62355

Here is full logs:
Freeswitch from repo:
recv 2727 bytes from ws/[192.168.0.100]:53867 at 13:57:57.796818:

INVITE sip:200@192.168.0.198 SIP/2.0
Via: SIP/2.0/WS kpucsars9g8e.invalid;branch=z9hG4bK8643725
Max-Forwards: 69
To: sip:200@192.168.0.198
From: "1100" sip:1100@192.168.0.198;tag=jm7gktle5o
Call-ID: jhc4j1qq70aki77o8k8f
CSeq: 2291 INVITE
Contact: sip:i63mfpci@kpucsars9g8e.invalid;transport=ws;ob
Content-Type: application/sdp
Session-Expires: 120
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: timer,ice,replaces,outbound
User-Agent: JsSIP 3.4.3
Content-Length: 2203

v=0
o=- 2429319989274798890 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=extmap-allow-mixed
a=msid-semantic: WMS Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP
m=audio 55731 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 my_wan_ip
a=rtcp:64332 IN IP4 my_wan_ip
a=candidate:2131708102 1 udp 2113937151 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 55731 typ host generation 0 network-cost 999
a=candidate:2131708102 2 udp 2113937150 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 64332 typ host generation 0 network-cost 999
a=candidate:842163049 2 udp 1677729534 my_wan_ip 64332 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=candidate:842163049 1 udp 1677729535 my_wan_ip 55731 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=ice-ufrag:cHVf
a=ice-pwd:ByCiaK0I6Gsr4jqJnXGValNx
a=ice-options:trickle
a=fingerprint:sha-256 BE:8D:0A:70:A8:24:F6:5B:59:7B:0E:F7:A1:7F:A3:A2:A7:B6:B1:9B:07:C4:D2:A1:8B:E2:82:B9:B4:7B:D2:F6
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=sendrecv
a=msid:Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP 5a7557c8-0513-4ddd-914b-9a16307e9acc
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:1638402901 cname:V0K9cBe/EAJxrMct
a=ssrc:1638402901 msid:Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP 5a7557c8-0513-4ddd-914b-9a16307e9acc
a=ssrc:1638402901 mslabel:Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP
a=ssrc:1638402901 label:5a7557c8-0513-4ddd-914b-9a16307e9acc
2021-03-31 13:57:57.788047 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/1100@192.168.0.198 [30bb4f79-7354-42cd-bb1d-40eb0d9c9105]
2021-03-31 13:57:57.788047 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1100@192.168.0.198) Running State Change CS_NEW (Cur 1 Tot 2)
2021-03-31 13:57:57.788047 [DEBUG] sofia.c:10279 sofia/internal/1100@192.168.0.198 receiving invite from 192.168.0.100:53867 version: 1.10.4 -release.6 64bit
2021-03-31 13:57:57.788047 [DEBUG] sofia.c:10373 verifying acl "domains" for ip/port 192.168.0.100:0.
2021-03-31 13:57:57.788047 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/1100@192.168.0.198) State NEW
send 830 bytes to ws/[192.168.0.100]:53867 at 13:57:57.799424:

SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/WS kpucsars9g8e.invalid;branch=z9hG4bK8643725;received=192.168.0.100;rport=53867
From: "1100" sip:1100@192.168.0.198;tag=jm7gktle5o
To: sip:200@192.168.0.198;tag=K6gQUtFe9Z5mB
Call-ID: jhc4j1qq70aki77o8k8f
CSeq: 2291 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.10.4-release.6~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Proxy-Authenticate: Digest realm="192.168.0.198", nonce="4514d6d3-7968-4839-affb-5070eb39031a", algorithm=MD5, qop="auth"
Content-Length: 0

2021-03-31 13:57:57.788047 [DEBUG] sofia.c:2434 detaching session 30bb4f79-7354-42cd-bb1d-40eb0d9c9105
recv 399 bytes from ws/[192.168.0.100]:53867 at 13:57:57.805717:

ACK sip:200@192.168.0.198 SIP/2.0
Via: SIP/2.0/WS kpucsars9g8e.invalid;branch=z9hG4bK8643725
Max-Forwards: 69
To: sip:200@192.168.0.198;tag=K6gQUtFe9Z5mB
From: "1100" sip:1100@192.168.0.198;tag=jm7gktle5o
Call-ID: jhc4j1qq70aki77o8k8f
CSeq: 2291 ACK
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.4.3
Content-Length: 0

recv 2976 bytes from ws/[192.168.0.100]:53867 at 13:57:57.809296:

INVITE sip:200@192.168.0.198 SIP/2.0
Via: SIP/2.0/WS kpucsars9g8e.invalid;branch=z9hG4bK6708119
Max-Forwards: 69
To: sip:200@192.168.0.198
From: "1100" sip:1100@192.168.0.198;tag=jm7gktle5o
Call-ID: jhc4j1qq70aki77o8k8f
CSeq: 2292 INVITE
Proxy-Authorization: Digest algorithm=MD5, username="1100", realm="192.168.0.198", nonce="4514d6d3-7968-4839-affb-5070eb39031a", uri="sip:200@192.168.0.198", response="71ce07e00bf874f410c37810374b9406", qop=auth, cnonce="g0uu1sojmc01", nc=00000001
Contact: sip:i63mfpci@kpucsars9g8e.invalid;transport=ws;ob
Content-Type: application/sdp
Session-Expires: 120
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: timer,ice,replaces,outbound
User-Agent: JsSIP 3.4.3
Content-Length: 2203

v=0
o=- 2429319989274798890 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=extmap-allow-mixed
a=msid-semantic: WMS Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP
m=audio 55731 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 my_wan_ip
a=rtcp:64332 IN IP4 my_wan_ip
a=candidate:2131708102 1 udp 2113937151 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 55731 typ host generation 0 network-cost 999
a=candidate:2131708102 2 udp 2113937150 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 64332 typ host generation 0 network-cost 999
a=candidate:842163049 2 udp 1677729534 my_wan_ip 64332 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=candidate:842163049 1 udp 1677729535 my_wan_ip 55731 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=ice-ufrag:cHVf
a=ice-pwd:ByCiaK0I6Gsr4jqJnXGValNx
a=ice-options:trickle
a=fingerprint:sha-256 BE:8D:0A:70:A8:24:F6:5B:59:7B:0E:F7:A1:7F:A3:A2:A7:B6:B1:9B:07:C4:D2:A1:8B:E2:82:B9:B4:7B:D2:F6
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=sendrecv
a=msid:Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP 5a7557c8-0513-4ddd-914b-9a16307e9acc
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:1638402901 cname:V0K9cBe/EAJxrMct
a=ssrc:1638402901 msid:Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP 5a7557c8-0513-4ddd-914b-9a16307e9acc
a=ssrc:1638402901 mslabel:Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP
a=ssrc:1638402901 label:5a7557c8-0513-4ddd-914b-9a16307e9acc
2021-03-31 13:57:57.808057 [DEBUG] sofia.c:2544 Re-attaching to session 30bb4f79-7354-42cd-bb1d-40eb0d9c9105
2021-03-31 13:57:57.808057 [DEBUG] sofia.c:10279 sofia/internal/1100@192.168.0.198 receiving invite from 192.168.0.100:53867 version: 1.10.4 -release.6 64bit
2021-03-31 13:57:57.808057 [DEBUG] sofia.c:10373 verifying acl "domains" for ip/port 192.168.0.100:0.
2021-03-31 13:57:57.808057 [DEBUG] sofia.c:11476 Setting NAT mode based on websockets
2021-03-31 13:57:57.808057 [DEBUG] sofia.c:7325 Channel sofia/internal/1100@192.168.0.198 entering state [received][100]
2021-03-31 13:57:57.808057 [DEBUG] sofia.c:7335 Remote SDP:
v=0
o=- 2429319989274798890 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=extmap-allow-mixed
a=msid-semantic: WMS Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP
m=audio 55731 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 my_wan_ip
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=rtcp:64332 IN IP4 my_wan_ip
a=candidate:2131708102 1 udp 2113937151 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 55731 typ host generation 0 network-cost 999
a=candidate:2131708102 2 udp 2113937150 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 64332 typ host generation 0 network-cost 999
a=candidate:842163049 2 udp 1677729534 my_wan_ip 64332 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=candidate:842163049 1 udp 1677729535 my_wan_ip 55731 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=ice-ufrag:cHVf
a=ice-pwd:ByCiaK0I6Gsr4jqJnXGValNx
a=ice-options:trickle
a=fingerprint:sha-256 BE:8D:0A:70:A8:24:F6:5B:59:7B:0E:F7:A1:7F:A3:A2:A7:B6:B1:9B:07:C4:D2:A1:8B:E2:82:B9:B4:7B:D2:F6
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=msid:Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP 5a7557c8-0513-4ddd-914b-9a16307e9acc
a=rtcp-mux
a=rtcp-fb:111 transport-cc
a=ssrc:1638402901 cname:V0K9cBe/EAJxrMct
a=ssrc:1638402901 msid:Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP 5a7557c8-0513-4ddd-914b-9a16307e9acc
a=ssrc:1638402901 mslabel:Nblmm3uDTfuZ84EHLhOU5oZJyLPkR8tEvigP
a=ssrc:1638402901 label:5a7557c8-0513-4ddd-914b-9a16307e9acc

2021-03-31 13:57:57.808057 [DEBUG] sofia.c:7738 (sofia/internal/1100@192.168.0.198) State Change CS_NEW -> CS_INIT
2021-03-31 13:57:57.808057 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1100@192.168.0.198) Running State Change CS_INIT (Cur 1 Tot 2)
2021-03-31 13:57:57.808057 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1100@192.168.0.198) State INIT
2021-03-31 13:57:57.808057 [DEBUG] mod_sofia.c:93 sofia/internal/1100@192.168.0.198 SOFIA INIT
2021-03-31 13:57:57.808057 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1100@192.168.0.198 Standard INIT
2021-03-31 13:57:57.808057 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1100@192.168.0.198) State Change CS_INIT -> CS_ROUTING
2021-03-31 13:57:57.808057 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1100@192.168.0.198) State INIT going to sleep
2021-03-31 13:57:57.808057 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1100@192.168.0.198) Running State Change CS_ROUTING (Cur 1 Tot 2)
2021-03-31 13:57:57.808057 [DEBUG] switch_channel.c:2332 (sofia/internal/1100@192.168.0.198) Callstate Change DOWN -> RINGING
2021-03-31 13:57:57.808057 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1100@192.168.0.198) State ROUTING
2021-03-31 13:57:57.808057 [DEBUG] mod_sofia.c:154 sofia/internal/1100@192.168.0.198 SOFIA ROUTING
2021-03-31 13:57:57.808057 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1100@192.168.0.198 Standard ROUTING
2021-03-31 13:57:57.808057 [INFO] mod_dialplan_xml.c:637 Processing 1100 <1100>->200 in context gaki_dialplan
send 326 bytes to ws/[192.168.0.100]:53867 at 13:57:57.826480:

SIP/2.0 100 Trying
Via: SIP/2.0/WS kpucsars9g8e.invalid;branch=z9hG4bK6708119;received=192.168.0.100;rport=53867
From: "1100" sip:1100@192.168.0.198;tag=jm7gktle5o
To: sip:200@192.168.0.198
Call-ID: jhc4j1qq70aki77o8k8f
CSeq: 2292 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.10.4-release.6~64bit
Content-Length: 0

Dialplan: sofia/internal/1100@192.168.0.198 parsing [gaki_dialplan->unloop] continue=false
Dialplan: sofia/internal/1100@192.168.0.198 Regex (FAIL) [unloop] true() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1100@192.168.0.198 parsing [gaki_dialplan->outbound_limit_check] continue=true
Dialplan: sofia/internal/1100@192.168.0.198 Regex (FAIL) [outbound_limit_check] destination_number(200) =~ /^attended_xfer_my_test.+$/ break=on-true
Dialplan: sofia/internal/1100@192.168.0.198 Absolute Condition [outbound_limit_check]
Dialplan: sofia/internal/1100@192.168.0.198 Action limit(db ${domain} ${a_leg} 1 outbound_over_limit XML system_actions)
Dialplan: sofia/internal/1100@192.168.0.198 parsing [gaki_dialplan->setOutgoingDestination] continue=true
Dialplan: sofia/internal/1100@192.168.0.198 Regex (FAIL) [setOutgoingDestination] destination_number(200) =~ /^attended_xfer_my_test.+$/ break=on-true
Dialplan: sofia/internal/1100@192.168.0.198 Absolute Condition [setOutgoingDestination]
Dialplan: sofia/internal/1100@192.168.0.198 Action execute_extension(setOutgoingDestination${destination_number} XML system_actions)
Dialplan: sofia/internal/1100@192.168.0.198 parsing [gaki_dialplan->test_check_called_user_status_variable] continue=false
Dialplan: sofia/internal/1100@192.168.0.198 Regex (FAIL) [test_check_called_user_status_variable] destination_number(200) =~ /^\d{4}$/ break=on-false
Dialplan: sofia/internal/1100@192.168.0.198 parsing [gaki_dialplan->sched_hangup_example] continue=false
Dialplan: sofia/internal/1100@192.168.0.198 Regex (FAIL) [sched_hangup_example] destination_number(200) =~ /^001$/ break=on-false
Dialplan: sofia/internal/1100@192.168.0.198 parsing [gaki_dialplan->blacklist_add] continue=false
Dialplan: sofia/internal/1100@192.168.0.198 Regex (FAIL) [blacklist_add] destination_number(200) =~ /^addBan(\d+)$/ break=on-false
Dialplan: sofia/internal/1100@192.168.0.198 parsing [gaki_dialplan->blacklist_check] continue=false
Dialplan: sofia/internal/1100@192.168.0.198 Regex (FAIL) [blacklist_check] destination_number(200) =~ /^checkBan(\d+)$/ break=on-false
Dialplan: sofia/internal/1100@192.168.0.198 parsing [gaki_dialplan->blacklist_delete] continue=false
Dialplan: sofia/internal/1100@192.168.0.198 Regex (FAIL) [blacklist_delete] destination_number(200) =~ /^delBan(\d+)$/ break=on-false
Dialplan: sofia/internal/1100@192.168.0.198 parsing [gaki_dialplan->call_spy_by_uuid] continue=false
Dialplan: sofia/internal/1100@192.168.0.198 Regex (FAIL) [call_spy_by_uuid] destination_number(200) =~ /^828(.+)$/ break=on-false
Dialplan: sofia/internal/1100@192.168.0.198 parsing [gaki_dialplan->UNKNOWN] continue=false
Dialplan: sofia/internal/1100@192.168.0.198 Regex (FAIL) [UNKNOWN] destination_number(200) =~ /^spy(.+)$/ break=on-false
Dialplan: sofia/internal/1100@192.168.0.198 parsing [gaki_dialplan->echo_test] continue=false
Dialplan: sofia/internal/1100@192.168.0.198 Regex (PASS) [echo_test] destination_number(200) =~ /^200$/ break=on-false
Dialplan: sofia/internal/1100@192.168.0.198 Action set(call_type=echo_test)
Dialplan: sofia/internal/1100@192.168.0.198 Action set(forced_set_b_legs_collocutors=system)
Dialplan: sofia/internal/1100@192.168.0.198 Action answer()
Dialplan: sofia/internal/1100@192.168.0.198 Action echo()
Dialplan: sofia/internal/1100@192.168.0.198 Action hangup()
2021-03-31 13:57:57.828005 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/1100@192.168.0.198) State Change CS_ROUTING -> CS_EXECUTE
2021-03-31 13:57:57.828005 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1100@192.168.0.198) State ROUTING going to sleep
2021-03-31 13:57:57.828005 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1100@192.168.0.198) Running State Change CS_EXECUTE (Cur 1 Tot 2)
2021-03-31 13:57:57.828005 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1100@192.168.0.198) State EXECUTE
2021-03-31 13:57:57.828005 [DEBUG] mod_sofia.c:209 sofia/internal/1100@192.168.0.198 SOFIA EXECUTE
2021-03-31 13:57:57.828005 [DEBUG] switch_core_state_machine.c:329 sofia/internal/1100@192.168.0.198 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/1100@192.168.0.198 limit(db 192.168.0.198 1100 1 outbound_over_limit XML system_actions)
2021-03-31 13:57:57.828005 [DEBUG] switch_limit.c:124 incr called: 192.168.0.198_1100 max:1, interval:0
2021-03-31 13:57:57.828005 [DEBUG] mod_db.c:194 Usage for 192.168.0.198_1100 is now 1/1
EXECUTE [depth=0] sofia/internal/1100@192.168.0.198 execute_extension(setOutgoingDestination200 XML system_actions)
2021-03-31 13:57:57.828005 [INFO] mod_dialplan_xml.c:637 Processing 1100 <1100>->setOutgoingDestination200 in context system_actions
Dialplan: sofia/internal/1100@192.168.0.198 parsing [system_actions->outbound_limit] continue=false
Dialplan: sofia/internal/1100@192.168.0.198 Regex (FAIL) [outbound_limit] destination_number(setOutgoingDestination200) =~ /^outbound_over_limit$/ break=on-false
Dialplan: sofia/internal/1100@192.168.0.198 parsing [system_actions->setOutgoingDestination] continue=false
Dialplan: sofia/internal/1100@192.168.0.198 Regex (PASS) [setOutgoingDestination] destination_number(setOutgoingDestination200) =~ /^setOutgoingDestination(.*)$/ break=on-false
Dialplan: sofia/internal/1100@192.168.0.198 Action set(outgoingDestinationNumber=200)
2021-03-31 13:57:57.828005 [NOTICE] switch_core_session.c:3017 Execute [depth=1] set(outgoingDestinationNumber=200)
EXECUTE [depth=1] sofia/internal/1100@192.168.0.198 set(outgoingDestinationNumber=200)
2021-03-31 13:57:57.828005 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1100@192.168.0.198 [outgoingDestinationNumber]=[200]
EXECUTE [depth=0] sofia/internal/1100@192.168.0.198 set(call_type=echo_test)
2021-03-31 13:57:57.828005 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1100@192.168.0.198 [call_type]=[echo_test]
EXECUTE [depth=0] sofia/internal/1100@192.168.0.198 set(forced_set_b_legs_collocutors=system)
2021-03-31 13:57:57.828005 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1100@192.168.0.198 [forced_set_b_legs_collocutors]=[system]
EXECUTE [depth=0] sofia/internal/1100@192.168.0.198 answer()
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:2]/[G722:9:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[G722:9:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[G722:9:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[G722:9:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[G722:9:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 110@48000
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:3839 Set Codec sofia/internal/1100@192.168.0.198 G722/8000 20 ms 160 samples 64000 bits 1 channels
2021-03-31 13:57:57.828005 [DEBUG] switch_core_codec.c:111 sofia/internal/1100@192.168.0.198 Original read codec set to G722:9
2021-03-31 13:57:57.828005 [WARNING] switch_core_media.c:4254 NO candidate ACL defined, Defaulting to wan.auto
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:4284 Save audio Candidate cid: 1 proto: udp type: host addr: 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local:55731
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:4284 Save audio Candidate cid: 2 proto: udp type: host addr: 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local:64332
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:4284 Save audio Candidate cid: 2 proto: udp type: srflx addr: my_wan_ip:64332
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:4284 Save audio Candidate cid: 1 proto: udp type: srflx addr: my_wan_ip:55731
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:4329 Searching for rtp candidate.
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:4338 Choose rtp candidate, index 1, my_wan_ip:55731
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:4104 sofia/internal/1100@192.168.0.198 choosing family v4
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:4349 Choose same candidate, index 2, for rtcp based on rtcp-mux attribute my_wan_ip:55731
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:4401 setting remote audio ice addr to index 1 my_wan_ip:55731 based on candidate
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:4436 Setting remote rtcp audio addr to my_wan_ip:55731 based on candidate
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5853 Set telephone-event payload to 126@8000
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:5911 sofia/internal/1100@192.168.0.198 Set 2833 dtmf send payload to 126 recv payload to 126
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:8663 AUDIO RTP [sofia/internal/1100@192.168.0.198] 192.168.0.198 port 30898 -> my_wan_ip port 55731 codec: 9 ms: 20
2021-03-31 13:57:57.828005 [DEBUG] switch_rtp.c:4450 Starting timer [soft] 160 bytes per 20ms
2021-03-31 13:57:57.828005 [INFO] switch_core_media.c:8845 Activating Audio ICE
2021-03-31 13:57:57.828005 [NOTICE] switch_rtp.c:4952 Activating RTP audio ICE: cHVf:vf4mjFfKQn14ej20 my_wan_ip:55731
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:8885 Activating RTCP PORT 55731
2021-03-31 13:57:57.828005 [DEBUG] switch_rtp.c:4848 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 55731
2021-03-31 13:57:57.828005 [INFO] switch_core_media.c:8896 Skipping RTCP ICE (Same as RTP)
2021-03-31 13:57:57.828005 [INFO] switch_rtp.c:3764 Activate RTP/RTCP audio DTLS client
2021-03-31 13:57:57.828005 [INFO] switch_rtp.c:3927 Changing audio DTLS state from OFF to HANDSHAKE
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:8977 sofia/internal/1100@192.168.0.198 Set 2833 dtmf send payload to 126
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:8984 sofia/internal/1100@192.168.0.198 Set 2833 dtmf receive payload to 126
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:9007 sofia/internal/1100@192.168.0.198 Set rtp dtmf delay to 40
2021-03-31 13:57:57.828005 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1100@192.168.0.198!
2021-03-31 13:57:57.828005 [DEBUG] switch_channel.c:3565 (sofia/internal/1100@192.168.0.198) Callstate Change RINGING -> EARLY
2021-03-31 13:57:57.828005 [DEBUG] switch_core_media.c:8645 Audio params are unchanged for sofia/internal/1100@192.168.0.198.
2021-03-31 13:57:57.828005 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/1100@192.168.0.198:
v=0
o=FreeSWITCH 1617157379 1617157380 IN IP4 192.168.0.198
s=FreeSWITCH
c=IN IP4 192.168.0.198
t=0 0
a=msid-semantic: WMS T410jaEqCRZ3TeigTRpg1dK2Bliqo0s8
m=audio 30898 UDP/TLS/RTP/SAVPF 9 126
a=rtpmap:9 G722/8000
a=rtpmap:126 telephone-event/8000
a=ptime:20
a=sendrecv
a=fingerprint:sha-256 E9:BF:B0:D3:13:23:83:C9:B1:B3:BB:9B:B2:3C:4F:96:89:F1:18:39:2F:65:F4:F9:40:95:7C:ED:7C:40:15:DE
a=setup:active
a=rtcp-mux
a=rtcp:30898 IN IP4 192.168.0.198
a=ice-ufrag:vf4mjFfKQn14ej20
a=ice-pwd:tQUD95g96MSbrJZNPU0Yp5y6
a=candidate:1472369171 1 udp 659136 192.168.0.198 30898 typ host generation 0
a=end-of-candidates
a=ssrc:2557402045 cname:VjY4kskMaaGTeO0Y
a=ssrc:2557402045 msid:T410jaEqCRZ3TeigTRpg1dK2Bliqo0s8 a0
a=ssrc:2557402045 mslabel:T410jaEqCRZ3TeigTRpg1dK2Bliqo0s8
a=ssrc:2557402045 label:T410jaEqCRZ3TeigTRpg1dK2Bliqo0s8a0

send 1772 bytes to ws/[192.168.0.100]:53867 at 13:57:57.845417:

SIP/2.0 200 OK
Via: SIP/2.0/WS kpucsars9g8e.invalid;branch=z9hG4bK6708119;received=192.168.0.100;rport=53867
From: "1100" sip:1100@192.168.0.198;tag=jm7gktle5o
To: sip:200@192.168.0.198;tag=mFagXN0H68U7p
Call-ID: jhc4j1qq70aki77o8k8f
CSeq: 2292 INVITE
Contact: sip:200@192.168.0.198:5060;transport=udp
User-Agent: FreeSWITCH-mod_sofia/1.10.4-release.6~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Require: timer
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 120;refresher=uac
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 840
Remote-Party-ID: "200" sip:200@192.168.0.198;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1617157379 1617157380 IN IP4 192.168.0.198
s=FreeSWITCH
c=IN IP4 192.168.0.198
t=0 0
a=msid-semantic: WMS T410jaEqCRZ3TeigTRpg1dK2Bliqo0s8
m=audio 30898 UDP/TLS/RTP/SAVPF 9 126
a=rtpmap:9 G722/8000
a=rtpmap:126 telephone-event/8000
a=ptime:20
a=fingerprint:sha-256 E9:BF:B0:D3:13:23:83:C9:B1:B3:BB:9B:B2:3C:4F:96:89:F1:18:39:2F:65:F4:F9:40:95:7C:ED:7C:40:15:DE
a=setup:active
a=rtcp-mux
a=rtcp:30898 IN IP4 192.168.0.198
a=ice-ufrag:vf4mjFfKQn14ej20
a=ice-pwd:tQUD95g96MSbrJZNPU0Yp5y6
a=candidate:1472369171 1 udp 659136 192.168.0.198 30898 typ host generation 0
a=end-of-candidates
a=ssrc:2557402045 cname:VjY4kskMaaGTeO0Y
a=ssrc:2557402045 msid:T410jaEqCRZ3TeigTRpg1dK2Bliqo0s8 a0
a=ssrc:2557402045 mslabel:T410jaEqCRZ3TeigTRpg1dK2Bliqo0s8
a=ssrc:2557402045 label:T410jaEqCRZ3TeigTRpg1dK2Bliqo0s8a0
recv 418 bytes from ws/[192.168.0.100]:53867 at 13:57:57.863469:

ACK sip:200@192.168.0.198:5060;transport=udp SIP/2.0
Via: SIP/2.0/WS kpucsars9g8e.invalid;branch=z9hG4bK1003077
Max-Forwards: 69
To: sip:200@192.168.0.198;tag=mFagXN0H68U7p
From: "1100" sip:1100@192.168.0.198;tag=jm7gktle5o
Call-ID: jhc4j1qq70aki77o8k8f
CSeq: 2292 ACK
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.4.3
Content-Length: 0

2021-03-31 13:57:57.867758 [DEBUG] sofia.c:7325 Channel sofia/internal/1100@192.168.0.198 entering state [completed][200]
2021-03-31 13:57:57.867758 [DEBUG] sofia.c:7325 Channel sofia/internal/1100@192.168.0.198 entering state [ready][200]
2021-03-31 13:57:59.007871 [NOTICE] switch_rtp.c:1301 Auto Changing audio stun/rtp/dtls port from my_wan_ip:55731 to 192.168.0.100:55731 idx:-1
2021-03-31 13:58:00.892307 [INFO] switch_rtp.c:3282 Changing audio DTLS state from HANDSHAKE to SETUP
2021-03-31 13:58:00.892307 [INFO] switch_rtp.c:3189 audio Fingerprint Verified.
2021-03-31 13:58:00.892307 [INFO] switch_rtp.c:4254 Activating audio Secure RTP SEND
2021-03-31 13:58:00.892307 [INFO] switch_rtp.c:4232 Activating audio Secure RTP RECV
2021-03-31 13:58:00.892307 [INFO] switch_rtp.c:3231 Changing audio DTLS state from SETUP to READY
2021-03-31 13:58:00.892307 [NOTICE] mod_dptools.c:1406 Channel [sofia/internal/1100@192.168.0.198] has been answered
2021-03-31 13:58:00.892307 [DEBUG] switch_channel.c:3865 (sofia/internal/1100@192.168.0.198) Callstate Change EARLY -> ACTIVE
EXECUTE [depth=0] sofia/internal/1100@192.168.0.198 echo()
2021-03-31 13:58:00.892307 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80
2021-03-31 13:58:00.892307 [DEBUG] switch_rtp.c:1921 rtcp_stats_init: audio ssrc[1638402901] base_seq[2159]
2021-03-31 13:58:00.892307 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80
recv 418 bytes from ws/[192.168.0.100]:53867 at 13:58:08.640621:

BYE sip:200@192.168.0.198:5060;transport=udp SIP/2.0
Via: SIP/2.0/WS kpucsars9g8e.invalid;branch=z9hG4bK7046551
Max-Forwards: 69
To: sip:200@192.168.0.198;tag=mFagXN0H68U7p
From: "1100" sip:1100@192.168.0.198;tag=jm7gktle5o
Call-ID: jhc4j1qq70aki77o8k8f
CSeq: 2293 BYE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.4.3
Content-Length: 0

2021-03-31 13:58:08.627840 [NOTICE] sofia.c:1089 Hangup sofia/internal/1100@192.168.0.198 [CS_EXECUTE] [NORMAL_CLEARING]
2021-03-31 13:58:08.627840 [DEBUG] switch_core_session.c:2905 sofia/internal/1100@192.168.0.198 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2021-03-31 13:58:08.627840 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1100@192.168.0.198) State EXECUTE going to sleep
2021-03-31 13:58:08.627840 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1100@192.168.0.198) Running State Change CS_HANGUP (Cur 1 Tot 2)
2021-03-31 13:58:08.627840 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/1100@192.168.0.198) Callstate Change ACTIVE -> HANGUP
2021-03-31 13:58:08.627840 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1100@192.168.0.198) State HANGUP
2021-03-31 13:58:08.627840 [DEBUG] mod_sofia.c:453 Channel sofia/internal/1100@192.168.0.198 hanging up, cause: NORMAL_CLEARING
2021-03-31 13:58:08.627840 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1100@192.168.0.198 Standard HANGUP, cause: NORMAL_CLEARING
2021-03-31 13:58:08.627840 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1100@192.168.0.198) State HANGUP going to sleep
2021-03-31 13:58:08.627840 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/1100@192.168.0.198) State Change CS_HANGUP -> CS_REPORTING
2021-03-31 13:58:08.627840 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1100@192.168.0.198) Running State Change CS_REPORTING (Cur 1 Tot 2)
2021-03-31 13:58:08.627840 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/1100@192.168.0.198) State REPORTING
send 481 bytes to ws/[192.168.0.100]:53867 at 13:58:08.649404:

SIP/2.0 200 OK
Via: SIP/2.0/WS kpucsars9g8e.invalid;branch=z9hG4bK7046551;received=192.168.0.100;rport=53867
From: "1100" sip:1100@192.168.0.198;tag=jm7gktle5o
To: sip:200@192.168.0.198;tag=mFagXN0H68U7p
Call-ID: jhc4j1qq70aki77o8k8f
CSeq: 2293 BYE
User-Agent: FreeSWITCH-mod_sofia/1.10.4-release.6~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Content-Length: 0

2021-03-31 13:58:08.687780 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1100@192.168.0.198 Standard REPORTING, cause: NORMAL_CLEARING
2021-03-31 13:58:08.687780 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/1100@192.168.0.198) State REPORTING going to sleep
2021-03-31 13:58:08.687780 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/1100@192.168.0.198) State Change CS_REPORTING -> CS_DESTROY
2021-03-31 13:58:08.687780 [DEBUG] switch_core_session.c:1726 Session 2 (sofia/internal/1100@192.168.0.198) Locked, Waiting on external entities
2021-03-31 13:58:08.687780 [NOTICE] switch_core_session.c:1744 Session 2 (sofia/internal/1100@192.168.0.198) Ended
2021-03-31 13:58:08.687780 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/1100@192.168.0.198 [CS_DESTROY]
2021-03-31 13:58:08.687780 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/1100@192.168.0.198) Running State Change CS_DESTROY (Cur 0 Tot 2)
2021-03-31 13:58:08.687780 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/1100@192.168.0.198) State DESTROY
2021-03-31 13:58:08.687780 [DEBUG] mod_sofia.c:364 sofia/internal/1100@192.168.0.198 SOFIA DESTROY
2021-03-31 13:58:08.687780 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1100@192.168.0.198 Standard DESTROY
2021-03-31 13:58:08.687780 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/1100@192.168.0.198) State DESTROY going to sleep

Freeswitch from source code:
recv 2727 bytes from ws/[192.168.0.100]:51173 at 13:47:10.747831:

INVITE sip:200@192.168.0.222 SIP/2.0
Via: SIP/2.0/WS v8jh7lb7gamh.invalid;branch=z9hG4bK1915969
Max-Forwards: 69
To: sip:200@192.168.0.222
From: "1000" sip:1000@192.168.0.222;tag=3uj1o0dhhj
Call-ID: 7rpbljdd1k07vci3sae9
CSeq: 8778 INVITE
Contact: sip:v55ee8j2@v8jh7lb7gamh.invalid;transport=ws;ob
Content-Type: application/sdp
Session-Expires: 120
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: timer,ice,replaces,outbound
User-Agent: JsSIP 3.4.3
Content-Length: 2203

v=0
o=- 5047170080915542465 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=extmap-allow-mixed
a=msid-semantic: WMS h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR
m=audio 62355 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 my_wan_ip
a=rtcp:52313 IN IP4 my_wan_ip
a=candidate:2131708102 1 udp 2113937151 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 62355 typ host generation 0 network-cost 999
a=candidate:2131708102 2 udp 2113937150 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 52313 typ host generation 0 network-cost 999
a=candidate:842163049 1 udp 1677729535 my_wan_ip 62355 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=candidate:842163049 2 udp 1677729534 my_wan_ip 52313 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=ice-ufrag:s4tw
a=ice-pwd:hCtFLELZlJTsgkdIlU9EGsZN
a=ice-options:trickle
a=fingerprint:sha-256 58:33:20:CC:00:2B:ED:E5:20:58:F2:21:50:A8:F7:28:66:3E:E6:16:E9:7F:62:B5:B8:9A:48:06:60:76:8B:C4
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=sendrecv
a=msid:h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR 0e21ebbe-1987-4724-9b3d-7ec3d0bd9c10
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:2972185675 cname:LnFuCgi6UR81OGZM
a=ssrc:2972185675 msid:h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR 0e21ebbe-1987-4724-9b3d-7ec3d0bd9c10
a=ssrc:2972185675 mslabel:h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR
a=ssrc:2972185675 label:0e21ebbe-1987-4724-9b3d-7ec3d0bd9c10
2021-03-31 13:47:10.732762 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/1000@192.168.0.222 [445cf7f1-901a-4dae-85b9-6e9a459c07c2]
2021-03-31 13:47:10.732762 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1000@192.168.0.222) Running State Change CS_NEW (Cur 1 Tot 1)
2021-03-31 13:47:10.732762 [INFO] sofia.c:10362 sofia/internal/1000@192.168.0.222 receiving invite from 192.168.0.100:51173 version: 1.10.6-release 64bit call-id: 7rpbljdd1k07vci3sae9
2021-03-31 13:47:10.751586 [DEBUG] sofia.c:10456 verifying acl "domains" for ip/port 192.168.0.100:0.
2021-03-31 13:47:10.751586 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/1000@192.168.0.222) State NEW
send 828 bytes to ws/[192.168.0.100]:51173 at 13:47:10.752885:

SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/WS v8jh7lb7gamh.invalid;branch=z9hG4bK1915969;received=192.168.0.100;rport=51173
From: "1000" sip:1000@192.168.0.222;tag=3uj1o0dhhj
To: sip:200@192.168.0.222;tag=vv0vyQrtDt2tc
Call-ID: 7rpbljdd1k07vci3sae9
CSeq: 8778 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.10.6-release~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Proxy-Authenticate: Digest realm="192.168.0.222", nonce="46937cee-bbf6-4104-a0e7-a04b09573c68", algorithm=MD5, qop="auth"
Content-Length: 0

2021-03-31 13:47:10.751586 [DEBUG] sofia.c:2447 detaching session 445cf7f1-901a-4dae-85b9-6e9a459c07c2
recv 399 bytes from ws/[192.168.0.100]:51173 at 13:47:10.756618:

ACK sip:200@192.168.0.222 SIP/2.0
Via: SIP/2.0/WS v8jh7lb7gamh.invalid;branch=z9hG4bK1915969
Max-Forwards: 69
To: sip:200@192.168.0.222;tag=vv0vyQrtDt2tc
From: "1000" sip:1000@192.168.0.222;tag=3uj1o0dhhj
Call-ID: 7rpbljdd1k07vci3sae9
CSeq: 8778 ACK
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.4.3
Content-Length: 0

recv 2976 bytes from ws/[192.168.0.100]:51173 at 13:47:10.760218:

INVITE sip:200@192.168.0.222 SIP/2.0
Via: SIP/2.0/WS v8jh7lb7gamh.invalid;branch=z9hG4bK5198606
Max-Forwards: 69
To: sip:200@192.168.0.222
From: "1000" sip:1000@192.168.0.222;tag=3uj1o0dhhj
Call-ID: 7rpbljdd1k07vci3sae9
CSeq: 8779 INVITE
Proxy-Authorization: Digest algorithm=MD5, username="1000", realm="192.168.0.222", nonce="46937cee-bbf6-4104-a0e7-a04b09573c68", uri="sip:200@192.168.0.222", response="c041e6cfd4f57f892206323b73700ec9", qop=auth, cnonce="kgujdi2k8gpi", nc=00000001
Contact: sip:v55ee8j2@v8jh7lb7gamh.invalid;transport=ws;ob
Content-Type: application/sdp
Session-Expires: 120
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: timer,ice,replaces,outbound
User-Agent: JsSIP 3.4.3
Content-Length: 2203

v=0
o=- 5047170080915542465 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=extmap-allow-mixed
a=msid-semantic: WMS h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR
m=audio 62355 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 my_wan_ip
a=rtcp:52313 IN IP4 my_wan_ip
a=candidate:2131708102 1 udp 2113937151 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 62355 typ host generation 0 network-cost 999
a=candidate:2131708102 2 udp 2113937150 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 52313 typ host generation 0 network-cost 999
a=candidate:842163049 1 udp 1677729535 my_wan_ip 62355 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=candidate:842163049 2 udp 1677729534 my_wan_ip 52313 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=ice-ufrag:s4tw
a=ice-pwd:hCtFLELZlJTsgkdIlU9EGsZN
a=ice-options:trickle
a=fingerprint:sha-256 58:33:20:CC:00:2B:ED:E5:20:58:F2:21:50:A8:F7:28:66:3E:E6:16:E9:7F:62:B5:B8:9A:48:06:60:76:8B:C4
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=sendrecv
a=msid:h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR 0e21ebbe-1987-4724-9b3d-7ec3d0bd9c10
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:2972185675 cname:LnFuCgi6UR81OGZM
a=ssrc:2972185675 msid:h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR 0e21ebbe-1987-4724-9b3d-7ec3d0bd9c10
a=ssrc:2972185675 mslabel:h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR
a=ssrc:2972185675 label:0e21ebbe-1987-4724-9b3d-7ec3d0bd9c10
2021-03-31 13:47:10.751586 [DEBUG] sofia.c:2562 Re-attaching to session 445cf7f1-901a-4dae-85b9-6e9a459c07c2
2021-03-31 13:47:10.772409 [INFO] sofia.c:10362 sofia/internal/1000@192.168.0.222 receiving invite from 192.168.0.100:51173 version: 1.10.6-release 64bit call-id: 7rpbljdd1k07vci3sae9
2021-03-31 13:47:10.772409 [DEBUG] sofia.c:10456 verifying acl "domains" for ip/port 192.168.0.100:0.
2021-03-31 13:47:10.772409 [DEBUG] sofia.c:11564 Setting NAT mode based on websockets
2021-03-31 13:47:10.772409 [DEBUG] sofia.c:7406 Channel sofia/internal/1000@192.168.0.222 entering state [received][100]
2021-03-31 13:47:10.772409 [DEBUG] sofia.c:7416 Remote SDP:
v=0
o=- 5047170080915542465 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=extmap-allow-mixed
a=msid-semantic: WMS h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR
m=audio 62355 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 my_wan_ip
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=rtcp:52313 IN IP4 my_wan_ip
a=candidate:2131708102 1 udp 2113937151 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 62355 typ host generation 0 network-cost 999
a=candidate:2131708102 2 udp 2113937150 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local 52313 typ host generation 0 network-cost 999
a=candidate:842163049 1 udp 1677729535 my_wan_ip 62355 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=candidate:842163049 2 udp 1677729534 my_wan_ip 52313 typ srflx raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=ice-ufrag:s4tw
a=ice-pwd:hCtFLELZlJTsgkdIlU9EGsZN
a=ice-options:trickle
a=fingerprint:sha-256 58:33:20:CC:00:2B:ED:E5:20:58:F2:21:50:A8:F7:28:66:3E:E6:16:E9:7F:62:B5:B8:9A:48:06:60:76:8B:C4
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=msid:h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR 0e21ebbe-1987-4724-9b3d-7ec3d0bd9c10
a=rtcp-mux
a=rtcp-fb:111 transport-cc
a=ssrc:2972185675 cname:LnFuCgi6UR81OGZM
a=ssrc:2972185675 msid:h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR 0e21ebbe-1987-4724-9b3d-7ec3d0bd9c10
a=ssrc:2972185675 mslabel:h9jT2eHWVbG0lCcxEDGIWgmQjZHDpgiPZHCR
a=ssrc:2972185675 label:0e21ebbe-1987-4724-9b3d-7ec3d0bd9c10

2021-03-31 13:47:10.772409 [DEBUG] sofia.c:7819 (sofia/internal/1000@192.168.0.222) State Change CS_NEW -> CS_INIT
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1000@192.168.0.222) Running State Change CS_INIT (Cur 1 Tot 1)
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1000@192.168.0.222) State INIT
2021-03-31 13:47:10.772409 [DEBUG] mod_sofia.c:93 sofia/internal/1000@192.168.0.222 SOFIA INIT
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@192.168.0.222 Standard INIT
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000@192.168.0.222) State Change CS_INIT -> CS_ROUTING
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1000@192.168.0.222) State INIT going to sleep
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1000@192.168.0.222) Running State Change CS_ROUTING (Cur 1 Tot 1)
2021-03-31 13:47:10.772409 [DEBUG] switch_channel.c:2332 (sofia/internal/1000@192.168.0.222) Callstate Change DOWN -> RINGING
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1000@192.168.0.222) State ROUTING
2021-03-31 13:47:10.772409 [DEBUG] mod_sofia.c:154 sofia/internal/1000@192.168.0.222 SOFIA ROUTING
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1000@192.168.0.222 Standard ROUTING
2021-03-31 13:47:10.772409 [INFO] mod_dialplan_xml.c:637 Processing 1000 <1000>->200 in context default
Dialplan: sofia/internal/1000@192.168.0.222 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1000@192.168.0.222 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
send 324 bytes to ws/[192.168.0.100]:51173 at 13:47:10.775518:

SIP/2.0 100 Trying
Via: SIP/2.0/WS v8jh7lb7gamh.invalid;branch=z9hG4bK5198606;received=192.168.0.100;rport=51173
From: "1000" sip:1000@192.168.0.222;tag=3uj1o0dhhj
To: sip:200@192.168.0.222
Call-ID: 7rpbljdd1k07vci3sae9
CSeq: 8779 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.10.6-release~64bit
Content-Length: 0

Dialplan: sofia/internal/1000@192.168.0.222 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1000@192.168.0.222 parsing [default->echo_test] continue=false
Dialplan: sofia/internal/1000@192.168.0.222 Regex (PASS) [echo_test] destination_number(200) =~ /^200$/ break=on-false
Dialplan: sofia/internal/1000@192.168.0.222 Action answer()
Dialplan: sofia/internal/1000@192.168.0.222 Action echo()
Dialplan: sofia/internal/1000@192.168.0.222 Action hangup()
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/1000@192.168.0.222) State Change CS_ROUTING -> CS_EXECUTE
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1000@192.168.0.222) State ROUTING going to sleep
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1000@192.168.0.222) Running State Change CS_EXECUTE (Cur 1 Tot 1)
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1000@192.168.0.222) State EXECUTE
2021-03-31 13:47:10.772409 [DEBUG] mod_sofia.c:209 sofia/internal/1000@192.168.0.222 SOFIA EXECUTE
2021-03-31 13:47:10.772409 [DEBUG] switch_core_state_machine.c:329 sofia/internal/1000@192.168.0.222 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/1000@192.168.0.222 answer()
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [opus:111:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [opus:111:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5656 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5656 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5517 Set telephone-event payload to 110@48000
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:3847 Set Codec sofia/internal/1000@192.168.0.222 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2021-03-31 13:47:10.772409 [DEBUG] switch_core_codec.c:111 sofia/internal/1000@192.168.0.222 Original read codec set to PCMU:0
2021-03-31 13:47:10.772409 [WARNING] switch_core_media.c:4265 NO candidate ACL defined, Defaulting to wan.auto
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:4295 Save audio Candidate cid: 1 proto: udp type: host addr: 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local:62355
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:4295 Save audio Candidate cid: 2 proto: udp type: host addr: 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local:52313
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:4295 Save audio Candidate cid: 1 proto: udp type: srflx addr: my_wan_ip:62355
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:4295 Save audio Candidate cid: 2 proto: udp type: srflx addr: my_wan_ip:52313
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:4340 Searching for rtp candidate.
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:4349 Choose rtp candidate, index 0, 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local:62355
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:4115 sofia/internal/1000@192.168.0.222 choosing family v4
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:4360 Choose same candidate, index 2, for rtcp based on rtcp-mux attribute 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local:62355
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:4412 setting remote audio ice addr to index 0 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local:62355 based on candidate
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:4447 Setting remote rtcp audio addr to 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local:62355 based on candidate
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5860 Set telephone-event payload to 126@8000
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:5918 sofia/internal/1000@192.168.0.222 Set 2833 dtmf send payload to 126 recv payload to 126
2021-03-31 13:47:10.772409 [DEBUG] switch_core_media.c:8675 AUDIO RTP [sofia/internal/1000@192.168.0.222] 192.168.0.222 port 31408 -> 4c20bd57-f5d9-4795-9c41-cacdec5cccd9.local port 62355 codec: 0 ms: 20
2021-03-31 13:47:10.772409 [DEBUG] switch_rtp.c:4478 Starting timer [soft] 160 bytes per 20ms
2021-03-31 13:47:11.232189 [ERR] switch_core_media.c:9685 AUDIO RTP REPORTS ERROR: [Remote Address Error!]
2021-03-31 13:47:11.232189 [NOTICE] switch_core_media.c:9686 Hangup sofia/internal/1000@192.168.0.222 [CS_EXECUTE] [INCOMPATIBLE_DESTINATION]
2021-03-31 13:47:11.232189 [DEBUG] switch_core_session.c:2914 sofia/internal/1000@192.168.0.222 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1000@192.168.0.222) State EXECUTE going to sleep
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1000@192.168.0.222) Running State Change CS_HANGUP (Cur 1 Tot 1)
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/1000@192.168.0.222) Callstate Change RINGING -> HANGUP
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1000@192.168.0.222) State HANGUP
2021-03-31 13:47:11.232189 [DEBUG] mod_sofia.c:453 Channel sofia/internal/1000@192.168.0.222 hanging up, cause: INCOMPATIBLE_DESTINATION
2021-03-31 13:47:11.232189 [DEBUG] mod_sofia.c:598 Responding to INVITE with: 488
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@192.168.0.222 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1000@192.168.0.222) State HANGUP going to sleep
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/1000@192.168.0.222) State Change CS_HANGUP -> CS_REPORTING
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1000@192.168.0.222) Running State Change CS_REPORTING (Cur 1 Tot 1)
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/1000@192.168.0.222) State REPORTING
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1000@192.168.0.222 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/1000@192.168.0.222) State REPORTING going to sleep
send 853 bytes to ws/[192.168.0.100]:51173 at 13:47:11.235875:

SIP/2.0 488 Not Acceptable Here
Via: SIP/2.0/WS v8jh7lb7gamh.invalid;branch=z9hG4bK5198606;received=192.168.0.100;rport=51173
Max-Forwards: 69
From: "1000" sip:1000@192.168.0.222;tag=3uj1o0dhhj
To: sip:200@192.168.0.222;tag=X5SN0j9Xa3rDr
Call-ID: 7rpbljdd1k07vci3sae9
CSeq: 8779 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.10.6-release~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Reason: Q.850;cause=88;text="INCOMPATIBLE_DESTINATION"
Content-Length: 0
Remote-Party-ID: "200" sip:200@192.168.0.222;party=calling;privacy=off;screen=no

2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/1000@192.168.0.222) State Change CS_REPORTING -> CS_DESTROY
2021-03-31 13:47:11.232189 [DEBUG] switch_core_session.c:1736 Session 1 (sofia/internal/1000@192.168.0.222) Locked, Waiting on external entities
2021-03-31 13:47:11.232189 [NOTICE] switch_core_session.c:1754 Session 1 (sofia/internal/1000@192.168.0.222) Ended
2021-03-31 13:47:11.232189 [NOTICE] switch_core_session.c:1758 Close Channel sofia/internal/1000@192.168.0.222 [CS_DESTROY]
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/1000@192.168.0.222) Running State Change CS_DESTROY (Cur 0 Tot 1)
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/1000@192.168.0.222) State DESTROY
2021-03-31 13:47:11.232189 [DEBUG] mod_sofia.c:364 sofia/internal/1000@192.168.0.222 SOFIA DESTROY
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1000@192.168.0.222 Standard DESTROY
2021-03-31 13:47:11.232189 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/1000@192.168.0.222) State DESTROY going to sleep
recv 399 bytes from ws/[192.168.0.100]:51173 at 13:47:11.240915:

ACK sip:200@192.168.0.222 SIP/2.0
Via: SIP/2.0/WS v8jh7lb7gamh.invalid;branch=z9hG4bK5198606
Max-Forwards: 69
To: sip:200@192.168.0.222;tag=X5SN0j9Xa3rDr
From: "1000" sip:1000@192.168.0.222;tag=3uj1o0dhhj
Call-ID: 7rpbljdd1k07vci3sae9
CSeq: 8779 ACK
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.4.3
Content-Length: 0

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions