I have two Asterisk servers setup on two different public IPs behind NAT.
I have endpoints connected to each asterisk server over PJSIP and everything works fine within each asterisk server. Calls can be made to other extensions on the same Asterisk server.
I have IAX2 trunks setup between the two Asterisk servers.
I am able to make calls between endpoints on different asterisk servers. The calls go through the IAX2 trunks fine and I can hear audio clearly on both ends. All is working well.
Except after 32 seconds it drops the calls. I see this NOTICE from Asteriskā¦
NOTICE[15707]: res_pjsip_transport_management.c:136 idle_sched_cb: Shutting down transport 'TCP to 192.168.1.10:50657' since no request was received in 32 seconds
This does not happen when making calls between endpoints on the same Asterisk server. Iāve even connected endpoints from an external IP to one of the Asterisk servers and made calls between endpoints there without issue. Just to ensure NAT was not a problem.
However Iām wondering if I missed a port for IAX2? Iāve only got the one port 4569 forwarded through on both routers. But this seems to be a PJSIP issue. Some sort of keep alive isnāt getting through the IAX2 trunk or something?
Hereās my iax.conf file for reference.
[general]
bindport = 4569
bindaddr = 0.0.0.0
disallow = all
allow = ulaw
allow = alaw
allow = gsm
mailboxdetail = yes
[server2]
type = friend
username = server1
secret = password
auth = plaintext
host = [EXTERNAL IP of SERVER 2]
port = 4569
context = fromiax
peercontext = fromiax
qualify = yes
trunk = yes
The second server is exactly the same except the context it connects to is [server1] and the username is set to server2 and the host is set to server 1ās ip.
Any thoughts or suggestions? Let me know if any further conf files are needed.
The PJSIP message has nothing to do with your IAX2 issue, in fact IAX2 doesnāt use TCP so there is no āconnectionā to close. Youāll need to provide further console output showing it actually dropping the call including āiax2 set debug onā to show the IAX2 messages.
Iāve done some more digging and I have a guess that this is a NAT issue. Maybe.
The call connects and I can hear both sides. However once thatās established could the destination IPās be getting re-written?
I guess what I need to know is that I had gotten the impression that all data went through the IAX2 trunk. Messaging and audio data. Which stands to reason since I havenāt setup any port forward for SIP. I expect it all to go through the IAX2 port. However once things are connected up could the two endpoints be trying to talk to each other directly? Looking at the SIP messages it seems as if one of the endpoints is trying to change things to the internal IPs which obviously wonāt work. Perhaps direct media or something?
Both sides wonāt go directly as the IAX2 trunk is in the middle. The hangup is coming from the remote side, so youād need to investigate further there to see why.
So I do have a double NAT situation going on. I have a pfsense firewall connected to the internet and I have a linux box setup for NATing and then the one asterisk server is behind that. Port forwards are obviously setup for IAX2 as the call is getting through and sound is heard on both sides.
The issue occurs if the call is initiated from a client on the other asterisk server. It comes in through IAX past the two routers and then to the asterisk server and then finally to the sip client. In this scenario the call drops at 32 seconds.
If however I initiate the call in the other direction, from a client connected to the double NATed Asterisk server. Then it works fine.
Iāve tried this outside of the double NATing scenario and it all works just fine. So the culprit is starting to point to the linux box acting as a router. Unfortunately my project has a requirement for this double NATing.
I read articles about some linux modules that could effect SIP traffic. However in this case it is IAX2 so Iām doubtful if these apply. There are three modules I can see with the name sip in them though. nf_conntrack_sip, ip_vs_pe_sip, nf_nat_sip.
Again the traffic is getting through. Itās as if some sort of keep alive message is not getting through on a different port. Which doesnāt make sense.
If SIP is in use, which I think it is (your statements are a bit unclear), then 32 seconds would be the retransmission timeout for 200 OK which would tear down the call. You would need to look into that. The IAX2 portion appears to be fine.
SIP is in use between endpoint and asterisk server. And then IAX2 is used between Asterisk servers.
It definitely seems like the SIP retransmission is the culprit. However what isnāt clear is why it all works when I move the double NATted asterisk server out to just a single nat.
The SIP retransmission timeout would be sent via sip to the asterisk server and then passed on through IAX to the other asterisk server and then sip to the second endpoint I assume?
Iāll try to grab some SIP logging again on both ends to see if there is anything I missed.
Hmm. Ok. The retransmission timeout would be between the endpoint and the asterisk server. That makes sense.
So I captured the sip logs. The call initiating end (the non-double NATted server) is very chatty compared to the other server. Hereās a break down on what I sawā¦
INVITE
Unauthorized
ACK
INVITE
TRYING
RINGING
OK
OK
OK
OPTIONS
OK
OK
OK
OK
OK
OK
REGISTER
Unauthorized
REGISTER
OK
OK
OK
OK
BYE
OK
On the Receiving call end I only see thisā¦
INVITE
TRYING
RINGING
OK
ACK
REGISTER
Unauthorized
REGISTER
OK
OPTIONS
OK
BYE
OK
I can post the entire sip logs but wanted to cut it down for brevity. Let me know and again very much appreciate the help and insight here. This one has me stumped.
You need to examine the 200 OK that is being retransmitted and look at the Contact header. If it contains an IP address and port that is not reachable by the endpoint then its ACK will get lost and you will see exactly what you are seeing. The āexternipā and ālocalnetā option would be used to configure it correctly.
Ok we are definitely narrowing in on the issue. The Contact header is set to the internal IP of the asterisk server. So that is confirmed to be the cause of the eventual timeout and BYE message.
Whatās odd is that both the external ip and local net settings are setupā¦ Hereās my config in pjsip.confā¦
[0.0.0.0-udp]
type=transport
protocol=udp
bind=0.0.0.0:5060
external_media_address=[EXTERNAL IP OF ASTERISK]
external_signaling_address=[EXTERNAL IP OF ASTERISK]
allow_reload=yes
local_net=[INTERNAL NETWORK OF ASTERISK]
Hereās the 200 OK SIP packet right after the RINGING. The packet after that is exactly the same tooā¦
<--- Transmitting SIP response (924 bytes) to UDP:[EXTERNAL IP OF ENDPOINT]:36286 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP [INTERNAL IP OF ENDPOINT]:52223;rport=36286;received=174.0.50.116;branch=z9hG4bKPj6BWl3l5Spkw-0vVeBgoDOAzFqgIZZegB
Call-ID: Dr3Kf1.BBtU1B711LO98YwmvjloSOTEA
From: "102" <sip:102@[EXTERNAL IP OF ASTERISK]>;tag=zoGSkMfXcskgs2E13CFt0ObUNrp0iIya
To: <sip:105@[EXTERNAL IP OF ASTERISK]>;tag=8779b34f-ad4d-4779-8912-9c906e32aba8
CSeq: 14135 INVITE
Server: Asterisk PBX 13.17.2
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE
Contact: <sip:[INTERNAL IP OF ASTERISK]:5060>
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length: 260
v=0
o=- 3716918425 3716918427 IN IP4 [INTERNAL IP OF ASTERISK]
s=Asterisk
c=IN IP4 [EXTERNAL IP OF ASTERISK]
t=0 0
m=audio 15602 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
Important to note that the endpoint is behind NAT. So thatās why you see [EXTERNAL IP OF ENDPOINT].
Let me know if youād like to see actual IP addresses. Perhaps I can send them in a private message some how. For clarity, none of the IPās are in each otherās subnets. So for example the internal IP of the endpoint is in the 10.x range whereas the internal network of the asterisk server is in a 172 range.
Iām confused here because this issue only occurs if this endpoint initiates the call. If this endpoint receives the call then it works fine.
What version of Asterisk is in use? As for receiving the call, that would change the direction of the 200 OK and Asterisk would be able to send back the ACK so it would be fine.
Ah, I can see from the signaling it is 13.17.2. I know of no issues with that and NAT like this. I donāt know why we wouldnāt update the Contact address to the proper thing. If you turn up core debug (configure logger.conf to send debug to console, and do core set debug 9) then the module responsible for it will spit out stuff as it determines whether to or not.
Ok so I grabbed the debug logs. Thereās a lot of data obviously at level 9. But I went through it all and identified a number of lines such asā¦
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip/pjsip_message_ip_updater.c:287 multihomed_on_tx_message: Re-wrote Contact URI host/port to [ASTERISK INTERNAL IP]:5060
This line appears numerous times from the start through until the 32 seconds are up. Obviously the retries happening as you mentioned.
However there does not appear to be any obvious reason here for it. Hereās a snippet around the first such case for more detailā¦
[Oct 15 08:49:40] DEBUG[31601]: app_queue.c:2485 device_state_cb: Device 'IAX2/client-2' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Oct 15 08:49:40] DEBUG[31586]: manager.c:5867 match_filter: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: IAX2/client-2
State: RINGING
[Oct 15 08:49:40] DEBUG[31531]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - 102
[Oct 15 08:49:40] DEBUG[31531]: devicestate.c:474 do_state_change: Changing state for PJSIP/102 - state 2 (In use)
[Oct 15 08:49:40] DEBUG[31601]: app_queue.c:2485 device_state_cb: Device 'PJSIP/102' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2532 handle_outgoing_response: Method is INVITE, Response is 180 Ringing
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip/pjsip_message_ip_updater.c:287 multihomed_on_tx_message: Re-wrote Contact URI host/port to [ASTERISK INTERNAL IP]:5060
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT EXTERNAL IP]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT EXTERNAL IP]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IP]:5060' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IP]' and port '5060'.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT EXTERNAL IP]:8874' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT EXTERNAL IP]' and port '8874'.
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '102(PJSIP/102-00000002)'
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f5afc00d418)
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is EARLY
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2633 session_inv_on_state_changed: Source of transaction state change is TX_MSG
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '102(PJSIP/102-00000002)'
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f5afc00d418)
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2447 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f5afc00d418
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Proceeding
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is TX_MSG
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is EARLY
Finally, hereās a snippet of the very beginning. I didnāt want to post the entire log as it is quite long. But I can do if that would be more helpful? Iām not exactly sure what to look for hereā¦
ip-[ASTERISK INTERNAL IP]*CLI> core set debug 9
Core debug was OFF and is now 9.
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT EXTERNAL IP]:8874' into...
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT EXTERNAL IP]' and port '8874'.
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IP]:5060' into...
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IP]' and port '5060'.
[Oct 15 08:49:40] DEBUG[31545]: res_pjsip/pjsip_distributor.c:383 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=30611 (rdata0x2f7b0d8)
[Oct 15 08:49:40] DEBUG[31545]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000026 to use for Request msg INVITE/cseq=30611 (rdata0x2f7b0d8)
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_endpoint_identifier_ip.c:212 ip_identify: No identify sections to match against
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_endpoint_identifier_user.c:133 username_identify: Attempting identify by From username '102' domain '[ASTERISK EXTERNAL IP]'
[Oct 15 08:49:40] DEBUG[31546]: db.c:376 db_get_common: Unable to find key '[ASTERISK EXTERNAL IP]' in family 'ps_domain_aliases/domain_alias'
[Oct 15 08:49:40] DEBUG[31546]: res_sorcery_astdb.c:209 sorcery_astdb_retrieve_id: Failed to retrieve object '[ASTERISK EXTERNAL IP]' from astdb
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_endpoint_identifier_user.c:145 username_identify: Identified by From username '102' domain '[ASTERISK EXTERNAL IP]'
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_authenticator_digest.c:454 digest_check_auth: Using default realm 'asterisk' on incoming auth '102-auth'.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IP]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IP]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT EXTERNAL IP]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT EXTERNAL IP]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT EXTERNAL IP]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT EXTERNAL IP]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IP]:5060' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IP]' and port '5060'.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT EXTERNAL IP]:8874' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT EXTERNAL IP]' and port '8874'.
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT EXTERNAL IP]:8874' into...
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT EXTERNAL IP]' and port '8874'.
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IP]:5060' into...
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IP]' and port '5060'.
[Oct 15 08:49:40] DEBUG[31545]: res_pjsip/pjsip_distributor.c:383 find_dialog: Could not find matching transaction for Request msg ACK/cseq=30611 (rdata0x2f7b0d8)
[Oct 15 08:49:40] DEBUG[31545]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000026 to use for Request msg ACK/cseq=30611 (rdata0x2f7b0d8)
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_endpoint_identifier_ip.c:212 ip_identify: No identify sections to match against
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_endpoint_identifier_user.c:133 username_identify: Attempting identify by From username '102' domain '[ASTERISK EXTERNAL IP]'
[Oct 15 08:49:40] DEBUG[31546]: db.c:376 db_get_common: Unable to find key '[ASTERISK EXTERNAL IP]' in family 'ps_domain_aliases/domain_alias'
[Oct 15 08:49:40] DEBUG[31546]: res_sorcery_astdb.c:209 sorcery_astdb_retrieve_id: Failed to retrieve object '[ASTERISK EXTERNAL IP]' from astdb
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_endpoint_identifier_user.c:145 username_identify: Identified by From username '102' domain '[ASTERISK EXTERNAL IP]'
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT EXTERNAL IP]:8874' into...
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT EXTERNAL IP]' and port '8874'.
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IP]:5060' into...
[Oct 15 08:49:40] DEBUG[31545]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IP]' and port '5060'.
[Oct 15 08:49:40] DEBUG[31545]: res_pjsip/pjsip_distributor.c:383 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=30612 (rdata0x2f7b0d8)
[Oct 15 08:49:40] DEBUG[31545]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000026 to use for Request msg INVITE/cseq=30612 (rdata0x2f7b0d8)
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_endpoint_identifier_ip.c:212 ip_identify: No identify sections to match against
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_endpoint_identifier_user.c:133 username_identify: Attempting identify by From username '102' domain '[ASTERISK EXTERNAL IP]'
[Oct 15 08:49:40] DEBUG[31546]: db.c:376 db_get_common: Unable to find key '[ASTERISK EXTERNAL IP]' in family 'ps_domain_aliases/domain_alias'
[Oct 15 08:49:40] DEBUG[31546]: res_sorcery_astdb.c:209 sorcery_astdb_retrieve_id: Failed to retrieve object '[ASTERISK EXTERNAL IP]' from astdb
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_endpoint_identifier_user.c:145 username_identify: Identified by From username '102' domain '[ASTERISK EXTERNAL IP]'
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_authenticator_digest.c:454 digest_check_auth: Using default realm 'asterisk' on incoming auth '102-auth'.
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_authenticator_digest.c:259 check_nonce: Calculated nonce 1508057380/d90702adefa20676eac04618935e68c8. Actual nonce is 1508057380/d90702adefa20676eac04618935e68c8
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IP]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IP]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT EXTERNAL IP]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT EXTERNAL IP]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000026 to use for Request msg INVITE/cseq=30612 (rdata0x318de28)
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2532 handle_outgoing_response: Method is INVITE, Response is 100 Trying
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT EXTERNAL IP]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT EXTERNAL IP]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IP]:5060' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IP]' and port '5060'.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT EXTERNAL IP]:8874' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT EXTERNAL IP]' and port '8874'.
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '102()'
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f5afc00d418)
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2456 __print_debug_details: There is no transaction involved in this state change
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is INCOMING
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2633 session_inv_on_state_changed: Source of transaction state change is TX_MSG
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2422 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2436 __print_debug_details: The state change pertains to the endpoint '102()'
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2441 __print_debug_details: The inv session still has an invite_tsx (0x7f5afc00d418)
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2447 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f5afc00d418
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2451 __print_debug_details: The current transaction state is Proceeding
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2453 __print_debug_details: The transaction state change event is TX_MSG
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:2458 __print_debug_details: The current inv state is INCOMING
[Oct 15 08:49:40] DEBUG[31546]: res_pjsip_session.c:269 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ENDPOINT INTERNAL IP]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ENDPOINT INTERNAL IP]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f5afc022670'
[Oct 15 08:49:40] DEBUG[31546]: res_rtp_asterisk.c:3058 ast_rtp_new: Allocated port 17126 for RTP instance '0x7f5afc022670'
[Oct 15 08:49:40] DEBUG[31546]: res_rtp_asterisk.c:3089 ast_rtp_new: Creating ICE session [::]:17126 (17126) for RTP instance '0x7f5afc022670'
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IPV6]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IPV6]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IPV6]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IPV6]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IP]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IP]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL IP]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL IP]' and port ''.
[Oct 15 08:49:40] DEBUG[31546]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7f5afc022670' is setup and ready to go
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '[ASTERISK INTERNAL HOSTNAME]' into...
[Oct 15 08:49:40] DEBUG[31546]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '[ASTERISK INTERNAL HOSTNAME]' and port ''.
This one definitely has me stumped. I have no idea why it would be using the internal IP in the CONTACT header. Doesnāt make sense. Also if the other endpoint is not behind this double NAT then it also works. But all that should be going through IAX2 anyway. ** EDIT ** Iāve also confirmed that if I initiate the call in the other direction, from the endpoint and asterisk server behind the double NAT, it works.
The only thing I can see is that the internal network of the Asterisk server is on the 172.31 network. Where as the second Asterisk and endpoint on the receiving end (behind the double nat) is on a 172.20 network. But the subnets are clearly defined and separate. Defined preparing in pjsip.conf as well. So thatās all a stretch but only thing I can think of so far. ** EDIT ** Confirmed this is not the issue as I setup an endpoint on a different subnet. Same issue.
Thanks again for any thoughts you may have. I know Iāve thrown out a lot here.
I had just completed spinning up an Asterisk 15.1.0 rc1 server and was about to setup the configs when I thought about playing around with the IP settings in the pjsip.conf file. In the external addresses I had set it to the hostname of the server *ie. pbx.myhostname.com". It looks like Asterisk does name resolution on the address before sending it out. This server was running on an AWS instance and I had setup the DNS entry for that hostname as a CNAME entry which pointed to the hostname that AWS generates. Well it turns out that if you try to resolve the public DNS hostname that AWS provides from the internal network of the AWS instance it resolves to the internal IP. So when Asterisk resolved the hostname it resolved from myhostname > AWS public Hostname > private IP.
I set the external address fields to the external IP address and then everything started working just fine. Whatās odd is this would only trigger under this odd circumstance of using IAX2 behind the double NAT. I canāt understand why things would work at all in this scenario. But something to investigate another day.
Ultimately what Iāve done is set the pjsip.conf external addresses back to my hostname entry as I had it before and just changed the DNS entry to instead be an A entry pointing to the external IP. That works just fine.
Thanks again for all the help Joshua. Very much appreciated! Hopefully this helps others in the future if they run across it.