[Home]

Summary:ASTERISK-29194: PJSIP NAT - rtp_symmetric not working
Reporter:Mark Murawski (kobaz)Labels:
Date Opened:2020-12-03 15:28:09.000-0600Date Closed:2020-12-03 18:47:45.000-0600
Priority:MajorRegression?
Status:Closed/CompleteComponents:Channels/chan_pjsip
Versions:16.15.0 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Attachments:
Description:In certain situations PJSIP does not respect local_net settings

Given the following setup:
{noformat}
21005            | endpoint/force_rport            | yes
21005            | endpoint/rewrite_contact        | yes
21005            | endpoint/rtp_symmetric          | yes

[transport-udp-lo]
type                       = transport
protocol                   = udp
bind                       = 127.0.0.1:5060
external_media_address     = 127.0.0.1
external_signaling_address = 127.0.0.1
external_signaling_port    = 5060
allow_reload               = yes
tos                        = cs3
cos                        = 3

[transport-udp-tun0]
type                       = transport
protocol                   = udp
bind                       = 10.1.2.20:5060
external_media_address     = 10.1.2.20
external_signaling_address = 10.1.2.20
external_signaling_port    = 5060
allow_reload               = yes
tos                        = cs3
cos                        = 3
local_net                  = 10.1.2.0/24

[transport-udp-tun1]
type                       = transport
protocol                   = udp
bind                       = 10.3.2.20:5060
external_media_address     = 10.3.2.20
external_signaling_address = 10.3.2.20
external_signaling_port    = 5060
allow_reload               = yes
tos                        = cs3
cos                        = 3
local_net                  = 10.3.2.0/24
{noformat}
And traffic coming into transport-udp-tun1
{noformat}
15:36:45.656238 IP 10.3.2.1.5060 > 10.3.2.20.5060: SIP: INVITE sip:*1234@10.3.2.20:5060;user=phone SIP/2.0
E`..B%..>...
...
...........INVITE sip:*1234@10.3.2.20:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.50.206;branch=z9hG4bKe661cfb7BD8F7712
From: "21005" <sip:21005@10.3.2.20>;tag=9BA63BB1-914B7CEC
To: <sip:*1234@10.3.2.20;user=phone>
CSeq: 1 INVITE
Call-ID: cfd9c5fd-64b01f78-fa86f683@192.168.50.206
Contact: <sip:21005@192.168.50.206>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_550-UA/4.0.15.1009
Accept-Language: en
Supported: 100rel,replaces
Allow-Events: conference,talk,hold
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 298

v=0
o=- 1607027804 1607027804 IN IP4 192.168.50.206
s=Polycom IP Phone
c=IN IP4 192.168.50.206
t=0 0
a=sendrecv
m=audio 2228 RTP/AVP 9 0 8 18 127
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:127 telephone-event/8000

15:36:45.657358 IP 10.3.2.20.5060 > 10.3.2.1.5060: SIP: SIP/2.0 401 Unauthorized
E`.Ry.@.@...
...
........>"#SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.50.206;rport=5060;received=10.3.2.1;branch=z9hG4bKe661cfb7BD8F7712
Call-ID: cfd9c5fd-64b01f78-fa86f683@192.168.50.206
From: "21005" <sip:21005@10.3.2.20>;tag=9BA63BB1-914B7CEC
To: <sip:*1234@10.3.2.20;user=phone>;tag=z9hG4bKe661cfb7BD8F7712
CSeq: 1 INVITE
WWW-Authenticate: Digest realm="asterisk",nonce="1607027805/57d9f055573ea588c2beb1f03c8e2bca",opaque="345e83785480fbf0",algorithm=md5,qop="auth"
Server: Asterisk PBX 16.15.0
Content-Length:  0


15:36:45.698544 IP 10.3.2.1.5060 > 10.3.2.20.5060: SIP: ACK sip:*1234@10.3.2.20:5060;user=phone SIP/2.0
E`.GB&..>. .
...
........3j.ACK sip:*1234@10.3.2.20:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.50.206;branch=z9hG4bKe661cfb7BD8F7712
From: "21005" <sip:21005@10.3.2.20>;tag=9BA63BB1-914B7CEC
To: <sip:*1234@10.3.2.20;user=phone>;tag=z9hG4bKe661cfb7BD8F7712
CSeq: 1 ACK
Call-ID: cfd9c5fd-64b01f78-fa86f683@192.168.50.206
Contact: <sip:21005@192.168.50.206>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_550-UA/4.0.15.1009
Accept-Language: en
Max-Forwards: 70
Content-Length: 0


15:36:45.698568 IP 10.3.2.1.5060 > 10.3.2.20.5060: SIP: INVITE sip:*1234@10.3.2.20:5060;user=phone SIP/2.0
E`..B'..>..n
...
..........6INVITE sip:*1234@10.3.2.20:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.50.206;branch=z9hG4bK3302ce1eA5B33949
From: "21005" <sip:21005@10.3.2.20>;tag=9BA63BB1-914B7CEC
To: <sip:*1234@10.3.2.20;user=phone>
CSeq: 2 INVITE
Call-ID: cfd9c5fd-64b01f78-fa86f683@192.168.50.206
Contact: <sip:21005@192.168.50.206>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_550-UA/4.0.15.1009
Accept-Language: en
Supported: 100rel,replaces
Allow-Events: conference,talk,hold
Authorization: Digest username="21005", realm="asterisk", nonce="1607027805/57d9f055573ea588c2beb1f03c8e2bca", qop=auth, cnonce="hTWM3tpAkuCZjNC", nc=00000001, opaque="345e83785480fbf0", uri="sip:*1234@10.3.2.20:5060;user=phone", response="7e4d360452dbfdf02c7297786403e104", algorithm=MD5
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 298

v=0
o=- 1607027804 1607027804 IN IP4 192.168.50.206
s=Polycom IP Phone
c=IN IP4 192.168.50.206
t=0 0
a=sendrecv
m=audio 2228 RTP/AVP 9 0 8 18 127
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:127 telephone-event/8000

15:36:45.701474 IP 10.3.2.20.5060 > 10.3.2.1.5060: SIP: SIP/2.0 100 Trying
E`..y3@.@...
...
...........SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.50.206;rport=5060;received=10.3.2.1;branch=z9hG4bK3302ce1eA5B33949
Call-ID: cfd9c5fd-64b01f78-fa86f683@192.168.50.206
From: "21005" <sip:21005@10.3.2.20>;tag=9BA63BB1-914B7CEC
To: <sip:*1234@10.3.2.20;user=phone>
CSeq: 2 INVITE
Server: Asterisk PBX 16.15.0
Content-Length:  0


15:36:45.716260 IP 10.3.2.20.5060 > 10.3.2.1.5060: SIP: SIP/2.0 200 OK
E`..y4@.@...
...
.........v.SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.50.206;rport=5060;received=10.3.2.1;branch=z9hG4bK3302ce1eA5B33949
Call-ID: cfd9c5fd-64b01f78-fa86f683@192.168.50.206
From: "21005" <sip:21005@10.3.2.20>;tag=9BA63BB1-914B7CEC
To: <sip:*1234@10.3.2.20;user=phone>;tag=9e82c96e-4b35-4ac9-a055-21970e96c5fd
CSeq: 2 INVITE
Server: Asterisk PBX 16.15.0
Contact: <sip:1.2.3.4:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   255

v=0
o=- 1607027804 1607027806 IN IP4 10.3.2.20
s=Asterisk
c=IN IP4 10.3.2.20
t=0 0
m=audio 16430 RTP/AVP 0 8 127
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:127 telephone-event/8000
a=fmtp:127 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
{noformat}
------------------

The following occurs:
{noformat}
Sent RTP packet to      192.168.50.206:2228 (type 00, seq 030925, ts 006080, len 000160)
Sent RTP packet to      192.168.50.206:2228 (type 00, seq 030926, ts 006240, len 000160)
Sent RTP packet to      192.168.50.206:2228 (type 00, seq 030927, ts 006400, len 000160)
Sent RTP packet to      192.168.50.206:2228 (type 00, seq 030928, ts 006560, len 000160)
Sent RTP packet to      192.168.50.206:2228 (type 00, seq 030929, ts 006720, len 000160)
Sent RTP packet to      192.168.50.206:2228 (type 00, seq 030930, ts 006880, len 000160)
Sent RTP packet to      192.168.50.206:2228 (type 00, seq 030931, ts 007040, len 000160)
Sent RTP packet to      192.168.50.206:2228 (type 00, seq 030932, ts 007200, len 000160)
Sent RTP packet to      192.168.50.206:2228 (type 00, seq 030933, ts 007360, len 000160)
{noformat}
Instead of sending to the expected rewrite_contact of 10.3.2.1
Comments:By: Asterisk Team (asteriskteam) 2020-12-03 15:28:10.820-0600

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.

Please note that by submitting data, code, or documentation to Sangoma through JIRA, you accept the Terms of Use present at [https://www.asterisk.org/terms-of-use/|https://www.asterisk.org/terms-of-use/].
By: Asterisk Team (asteriskteam) 2020-12-03 15:28:11.571-0600

The severity of this issue has been automatically downgraded from "Blocker" to "Major". The "Blocker" severity is reserved for issues which have been determined to block the next release of Asterisk. This severity can only be set by privileged users. If this issue is deemed to block the next release it will be updated accordingly during the triage process.
By: Joshua C. Colp (jcolp) 2020-12-03 15:37:41.496-0600

The "rewrite_contact" option controls SIP signaling. It changes the SIP contact of incoming SIP messages to be the actual source IP address and port. It has no influence over RTP.

The "rtp_symmetric" option would be the only one that does, which will send RTP to the source IP address and port from which it is received. Until RTP is received then Asterisk will send media to the IP address and port provided in the SDP.

As well the "local_net" option appears to be working fine. The IP address placed into the SDP and signaling from Asterisk is what I would expect.

By: Mark Murawski (kobaz) 2020-12-03 17:46:21.862-0600

Hi Josh,

So, I think the issue here is not specifically the rtp_symmetric, but the lack of actually 'seeing' rtp traffic hit the transport

On a new call:
tcpdump on the interface receiving traffic is showing RTP received:

# ip addr show tun1
4: tun1: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UNKNOWN group default qlen 100
   link/none
   inet 10.3.2.20 peer 10.3.2.21/32 scope global tun1

# tcpdump -i tun1 udp -n
18:41:08.756978 IP 10.3.2.1.2262 > 10.3.2.20.16598: UDP, length 172
18:41:08.779043 IP 10.3.2.1.2262 > 10.3.2.20.16598: UDP, length 172
18:41:08.796601 IP 10.3.2.1.2262 > 10.3.2.20.16598: UDP, length 172
18:41:08.819032 IP 10.3.2.1.2262 > 10.3.2.20.16598: UDP, length 172

Yet, a global 'rtp set debug on', shows the only RTP as what's going out to 192.168.50.206

The Asterisk rtp engine is not actually processing this.. I would expect that pjsip would be able to receive/process this traffic since it has a transport for this interface
Transport:  transport-udp-tun1        udp      3     96  10.3.2.20:5060

So, this is why the symmetric_rtp's not working, due to not actually getting rtp.



By: Joshua C. Colp (jcolp) 2020-12-03 18:04:53.388-0600

The transport is for SIP traffic, it doesn't have any influence over RTP. RTP is bound to wildcard for both IPv4 and IPv6 unless particular configuration is done. Have you examined the local listening RTP port with "netstat -an" to see if it is actually listening, and if any data is in Recv-Q that is not handled? Have you enabled core debug to see if any messages appear?
By: Mark Murawski (kobaz) 2020-12-03 18:15:22.033-0600

Outgoing from the 'remote' vpn client:
19:13:35.864957 IP 10.3.2.1.2226 > 10.3.2.20.16700: UDP, length 172
19:13:35.864997 IP 10.3.2.1.2226 > 10.3.2.20.16700: UDP, length 172

Incoming to the 'local' vpn client (on the asterisk server)
19:13:35.871314 IP 10.3.2.1.2226 > 10.3.2.20.16700: UDP, length 172
19:13:35.871409 IP 10.3.2.1.2226 > 10.3.2.20.16700: UDP, length 172

pbs-a {~} root# netstat -an | egrep "^udp" | grep 16700
pbs-a {~} root#

I'll start with some core debugging next
By: Mark Murawski (kobaz) 2020-12-03 18:23:53.539-0600

[2020-12-03 19:18:03.778] VERBOSE[19882] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '10.3.2.20'
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  21005: Call (UDP:10.3.2.1:5060) to extension '*1234' sending 100 Trying
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  21005: Method is INVITE, Response is 100 Trying
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  21005
[2020-12-03 19:18:03.778] DEBUG[19882] netsock2.c: Splitting '10.3.2.1' into...
[2020-12-03 19:18:03.778] DEBUG[19882] netsock2.c: ...host '10.3.2.1' and port ''.
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: The state change pertains to the endpoint '21005()'
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f27d8468d28)
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: There is no transaction involved in this state change
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: The current inv state is INCOMING
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: 21005: Source of transaction state change is TX_MSG
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: The state change pertains to the endpoint '21005()'
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f27d8468d28)
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f27d8468d28
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: The current transaction state is Proceeding
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: The transaction state change event is TX_MSG
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c: The current inv state is INCOMING
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  21005: Media count: 1
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  21005: Processing stream 0
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  21005: Using audio-0 for new stream name
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  21005: Using new stream 0:audio-0:audio:sendrecv (nothing)
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  21005 Adding position 0
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  Creating new media session
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  Setting media session as default for audio
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  Done
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_session.c:  21005: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler
[2020-12-03 19:18:03.778] DEBUG[19882] netsock2.c: Splitting '192.168.50.206' into...
[2020-12-03 19:18:03.778] DEBUG[19882] netsock2.c: ...host '192.168.50.206' and port ''.
[2020-12-03 19:18:03.778] DEBUG[19882] netsock2.c: Splitting '10.13.13.38' into...
[2020-12-03 19:18:03.778] DEBUG[19882] netsock2.c: ...host '10.13.13.38' and port ''.
[2020-12-03 19:18:03.778] DEBUG[19882] res_pjsip_sdp_rtp.c: Transport transport-udp bound to 10.13.13.38: Using it for RTP media.
[2020-12-03 19:18:03.778] DEBUG[19882] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x55d7279c1010'
[2020-12-03 19:18:03.778] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) RTP allocated port 16344
[2020-12-03 19:18:03.778] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) ICE creating session 10.13.13.38:16344 (16344)
[2020-12-03 19:18:03.778] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) ICE create
[2020-12-03 19:18:03.779] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) ICE add system candidates
[2020-12-03 19:18:03.779] DEBUG[19882] netsock2.c: Splitting '10.13.13.38' into...
[2020-12-03 19:18:03.779] DEBUG[19882] netsock2.c: ...host '10.13.13.38' and port ''.
[2020-12-03 19:18:03.779] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) ICE add candidate: 10.13.13.38:16344, 2130706431
[2020-12-03 19:18:03.779] DEBUG[19882] netsock2.c: Splitting '10.13.13.39' into...
[2020-12-03 19:18:03.779] DEBUG[19882] netsock2.c: ...host '10.13.13.39' and port ''.
[2020-12-03 19:18:03.779] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) ICE add candidate: 10.13.13.39:16344, 2130706431
[2020-12-03 19:18:03.779] DEBUG[19882] netsock2.c: Splitting '10.1.2.20' into...
[2020-12-03 19:18:03.779] DEBUG[19882] netsock2.c: ...host '10.1.2.20' and port ''.
[2020-12-03 19:18:03.779] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) ICE add candidate: 10.1.2.20:16344, 2130706431
[2020-12-03 19:18:03.779] DEBUG[19882] netsock2.c: Splitting '10.3.2.20' into...
[2020-12-03 19:18:03.779] DEBUG[19882] netsock2.c: ...host '10.3.2.20' and port ''.
[2020-12-03 19:18:03.779] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) ICE add candidate: 10.3.2.20:16344, 2130706431
[2020-12-03 19:18:03.779] DEBUG[19882] netsock2.c: Splitting '10.20.1.1' into...
[2020-12-03 19:18:03.779] DEBUG[19882] netsock2.c: ...host '10.20.1.1' and port ''.
[2020-12-03 19:18:03.779] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) ICE add candidate: 10.20.1.1:16344, 2130706431
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: RTP instance '0x55d7279c1010' is setup and ready to go
[2020-12-03 19:18:03.779] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) ICE stopped
[2020-12-03 19:18:03.779] DEBUG[19882] acl.c: Attached to given IP address
[2020-12-03 19:18:03.779] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) RTCP setup on RTP instance
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f27b646d340
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f27b646d340
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f27b646d340
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f27b646d340
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x55d727d75818) from 0x7f27b646d340 to 0x7f27b646d340
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x55d727dd73e8) from 0x7f27b646d340 to 0x7f27b646d340
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Crossover copying tx to rx payload mapping 9 (0x55d727a9d838) from 0x7f27b646d340 to 0x7f27b646d340
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x55d727ca0e98) from 0x7f27b646d340 to 0x7f27b646d340
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Crossover copying tx to rx payload mapping 127 (0x55d727ca5888) from 0x7f27b646d340 to 0x7f27b646d340
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Copying rx payload mapping 0 (0x55d727d75818) from 0x7f27b646d340 to 0x55d7279c11e8
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Copying rx payload mapping 8 (0x55d727dd73e8) from 0x7f27b646d340 to 0x55d7279c11e8
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Copying rx payload mapping 9 (0x55d727a9d838) from 0x7f27b646d340 to 0x55d7279c11e8
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Copying rx payload mapping 18 (0x55d727ca0e98) from 0x7f27b646d340 to 0x55d7279c11e8
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Copying rx payload mapping 127 (0x55d727ca5888) from 0x7f27b646d340 to 0x55d7279c11e8
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Copying tx payload mapping 0 (0x55d727d75818) from 0x7f27b646d340 to 0x55d7279c11e8
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Copying tx payload mapping 8 (0x55d727dd73e8) from 0x7f27b646d340 to 0x55d7279c11e8
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Copying tx payload mapping 9 (0x55d727a9d838) from 0x7f27b646d340 to 0x55d7279c11e8
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Copying tx payload mapping 18 (0x55d727ca0e98) from 0x7f27b646d340 to 0x55d7279c11e8
[2020-12-03 19:18:03.779] DEBUG[19882] rtp_engine.c: Copying tx payload mapping 127 (0x55d727ca5888) from 0x7f27b646d340 to 0x55d7279c11e8
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Media stream 0:audio-0:audio:sendrecv (ulaw|alaw) handled by audio
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Done with stream 0:audio-0:audio:sendrecv (ulaw|alaw)
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Handled? yes
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Processing streams
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Processing stream 0:audio-0:audio:sendrecv (ulaw|alaw)
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005 Adding position 0
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  Using existing media_session
[2020-12-03 19:18:03.779] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) RTCP ignoring duplicate property
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Stream 0:audio-0:audio:sendrecv (ulaw|alaw) added
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Done with 0:audio-0:audio:sendrecv (ulaw|alaw)
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Adding bundle groups (if available)
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Copying connection details
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Processing media 0
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Media 0 reset
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  21005: Method is INVITE
[2020-12-03 19:18:03.779] DEBUG[19882] chan_pjsip.c:  21005
[2020-12-03 19:18:03.779] DEBUG[19882] stasis.c: Creating topic. name: channel:1607041083.36, detail:
[2020-12-03 19:18:03.779] DEBUG[19882] stasis.c: Topic 'channel:1607041083.36': 0x55d7269dcd00 created
[2020-12-03 19:18:03.779] DEBUG[19882] stasis.c: Creating topic. name: cache:113/channel:1607041083.36, detail:
[2020-12-03 19:18:03.779] DEBUG[19882] stasis.c: Topic 'cache:113/channel:1607041083.36': 0x55d727e5cc10 created
[2020-12-03 19:18:03.779] DEBUG[19882] channel.c: Channel 0x55d727dd3d60 'PJSIP/21005-00000012' allocated
[2020-12-03 19:18:03.779] DEBUG[19882] chan_pjsip.c:  PJSIP/21005-00000012
[2020-12-03 19:18:03.779] DEBUG[19882] channel.c: Added datastore to channel 'PJSIP/21005-00000012', Type: T38 framehook, UID: (null)
[2020-12-03 19:18:03.779] DEBUG[19882] channel.c: Added datastore to channel 'PJSIP/21005-00000012', Type: FEATURE, UID: (null)
[2020-12-03 19:18:03.779] DEBUG[19882] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/21005-00000012
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  PJSIP/21005-00000012
[2020-12-03 19:18:03.779] DEBUG[19882] res_pjsip_session.c:  PJSIP/21005-00000012

So, I see a possible issue here:
[2020-12-03 19:18:03.778] DEBUG[19882] res_rtp_asterisk.c: (0x55d7279c1010) ICE creating session 10.13.13.38:16344 (16344)

So there's a little more to the story here.  There's some other transports that I didn't think were originally related, which are:
[transport-udp]
type                       = transport
protocol                   = udp
;disable_tcp_switch         = yes
bind                       = 10.13.13.38:5060
external_media_address     = 1.2.3.4 (ie: valid public ip)
external_signaling_address = 1.2.3.4 (ie: valid public ip)
external_signaling_port    = 5060
allow_reload               = yes
tos                        = cs3
cos                        = 3
local_net                  = 192.168.181.0/24
local_net                  = 10.13.13.0/24

[transport-tcp]
type                       = transport
protocol                   = tcp
bind                       = 10.13.13.38:5060
external_media_address     = 1.2.3.5 (ie: valid public ip)
external_signaling_address = 1.2.3.5 (ie: valid public ip)
external_signaling_port    = 5060
allow_reload               = yes
tos                        = cs3
cos                        = 3
local_net                  = 192.168.181.0/24

I'm registered to the 21005 endpoint via the transport-udp-tun1 transport, but it's trying to use the transport-udp instead?

By: Mark Murawski (kobaz) 2020-12-03 18:35:23.896-0600

{noformat}
21005            | type                            | wizard
21005            | accepts_registrations           | yes
21005            | accepts_auth                    | yes
21005            | has_hint                        | yes
21005            | hint_exten                      | 21005
21005            | aor/max_contacts                | 4
21005            | aor/remove_existing             | yes
21005            | endpoint/context                | cos_internal+local+ld
21005            | endpoint/callerid               | <21005>
21005            | endpoint/aggregate_mwi          | yes
21005            | endpoint/mailboxes              | 21005@internal
21005            | endpoint/ice_support            | no
21005            | inbound_auth/username           | 21005
21005            | inbound_auth/password           | somesortofpassword
21005            | outbound_auth/username          | 21005
21005            | outbound_auth/password          | somesortofpassword
21005            | aor/qualify_frequency           | 60
21005            | aor/qualify_timeout             | 2000
21005            | endpoint/allow                  | ulaw,alaw,adpcm,gsm
21005            | endpoint/allow_subscribe        | yes
21005            | endpoint/direct_media           | no
21005            | endpoint/disallow               | g723,slin,ilbc,lpc10,g729,speex,g726aal2,g722
21005            | endpoint/force_rport            | yes
21005            | endpoint/rewrite_contact        | yes
21005            | endpoint/rtp_symmetric          | yes
21005            | endpoint/rtp_timeout            | 60
21005            | endpoint/rtp_timeout_hold       | 60
21005            | endpoint/send_pai               | yes
21005            | endpoint/send_rpid              | yes
21005            | endpoint/subscribe_context      | blf
21005            | endpoint/transport              | transport-udp
21005            | endpoint/trust_id_inbound       | no
21005            | endpoint/trust_id_outbound      | yes
{noformat}
By: Mark Murawski (kobaz) 2020-12-03 18:43:01.000-0600

Thanks Josh!

Not a bug

Resolution: Remove per-endpoint transport=