Trying to set up this incoming SIP trunk (pjsip) from audiocodes to freepbx.
There’s an incoming trunk, incoming catch all routes, etc. Asterisk does not reply whatsoever to the INVITE. I had to turn on core set debug 9 to see that it it’s even trying to look at the INVITE because there’s absolutely no other events
I got the versions from the upgrade tool. Not sure how to go about upgrading the PHP to 7.4 but that’s another story
Your Asterisk version of 16.30.0 is supported
Your NodeJS Version of 8.16.0 is supported
Your SQL Version of 5.5.65 is supported
Your PHP version of 5.6.40 is NOT supported.
Your FreePBX Version of 15.0.37 is supported
Audiocodes retries the below INVITE a few times before it drops the call. I tried the from/to without the +1 and same issue
<--- Received SIP request (1045 bytes) from UDP:10.10.10.80:5060 --->
INVITE sip:[email protected];user=phone SIP/2.0
Via: SIP/2.0/UDP 10.10.10.80:5060;branch=z9hG4bKac1584388961
Max-Forwards: 70
From: "Name " <sip:[email protected]>;tag=1c762457173
To: <sip:[email protected];user=phone>
Call-ID: [email protected]
CSeq: 1 INVITE
Contact: <sip:[email protected]:5060>
Supported: em,100rel,timer,replaces,path,resource-priority,sdp-anat
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Session-Expires: 15;refresher=uac
Min-SE: 15
User-Agent: M800B/v.7.40A.250.541
Privacy: none
P-Asserted-Identity: "Name " <sip:[email protected]>
Content-Type: application/sdp
Content-Length: 301
v=0
o=AudiocodesGW 703143737 1011280034 IN IP4 10.10.10.80
s=Phone-Call
c=IN IP4 10.10.10.80
t=0 0
m=audio 6320 RTP/AVP 0 8 18 101
a=ptime:20
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
[2023-05-11 16:25:19] DEBUG[2134]: res_pjsip/pjsip_distributor.c:394 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7fd4180012b8)
[2023-05-11 16:25:19] DEBUG[2134]: res_pjsip/pjsip_distributor.c:472 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000038 to use for Request msg INVITE/cseq=1 (rdata0x7fd4180012b8)
[2023-05-11 16:25:19] DEBUG[19091]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '10.10.10.80' into...
[2023-05-11 16:25:19] DEBUG[19091]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '10.10.10.80' and port ''.
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 10.10.10.80:5060 does not match identify 'Perimeta'
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_endpoint_identifier_ip.c:255 ip_identify_match_check: Source address 10.10.10.80:5060 matches identify 'Audiocodes'
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_endpoint_identifier_ip.c:288 common_identify: Identify 'Audiocodes' SIP message matched to endpoint Audiocodes
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip/pjsip_distributor.c:472 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000038 to use for Request msg INVITE/cseq=1 (rdata0x7fd4180187a8)
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:3935 new_invite: Audiocodes
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4019 new_invite: Audiocodes: Call (UDP:10.10.10.80:5060) to extension '+1555123456' sending 100 Trying
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4334 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4348 __print_debug_details: The state change pertains to the endpoint 'Audiocodes()'
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4353 __print_debug_details: The inv session still has an invite_tsx (0x7fd408172d08)
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4368 __print_debug_details: There is no transaction involved in this state change
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4370 __print_debug_details: The current inv state is DISCONNCTD
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4617 session_inv_on_state_changed: Audiocodes: Source of transaction state change is USER
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4334 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4348 __print_debug_details: The state change pertains to the endpoint 'Audiocodes()'
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4356 __print_debug_details: The inv session does NOT have an invite_tsx
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4359 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7fd408172d08
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4363 __print_debug_details: The current transaction state is Terminated
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4365 __print_debug_details: The transaction state change event is USER
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4370 __print_debug_details: The current inv state is DISCONNCTD
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:4064 new_invite: Audiocodes
[2023-05-11 16:25:19] DEBUG[19091]: res_pjsip_session.c:2894 session_destructor: Audiocodes: Destroying SIP session
freepbx*CLI> pjsip show endpoints
Endpoint: Audiocodes Not in use 0 of inf
OutAuth: Audiocodes/Audiocodes
Aor: Audiocodes 0
Contact: Audiocodes/sip:[email protected]:5060 0cea0deaf9 Avail 31.726
Transport: 0.0.0.0-udp udp 3 96 0.0.0.0:5060
Identify: Audiocodes/Audiocodes
Match: 10.10.10.80/32
the log is from asterisk itself. the packet arrives and asterisk doesn’t process it. there’s nothing relevant before or after and it just repeats because audiocodes keeps retrying. the debug 9 is the only thing showing that asterisk is even trying to do something
asterisk -rvvvvvv
freepbx*CLI> core set debug 9
freepbx*CLI> pjsip set logger on
Esc Quit Enter Show Space Select F1 Help F2 Save F
10.10.10.80:5060 192.168.5.11:5060
----------+--------- ----------+---------
| INVITE (SDP) |
16:44:00.434706 | --------------------------> |
+0.513448 | INVITE (SDP) |
16:44:00.948154 | ------------------------>>> |
+1.001180 | INVITE (SDP) |
16:44:01.949334 | ------------------------>>> |
| |
| |
| |
| |
| |
| |
| |
| |
there’s no interconnect issue. what do you want to see to show you packets arrive at freepbx? i showed you the freepbx log, the sngrep as well
you can see freepbx tries to do something with the packet but it fails
I’d start at the Asterisk CLI to check if something even happen when the INVITE arrives.
Then check the firewall, it may be getting firewall’d. What you see in sngrep is at the network interface level, before it gets to asterisk or the firewall service itself.
You can ‘drill down’ by pressing enter on an ‘invite’, you will see the port and address of the invite and any response, apparently not here, who is 10.10.10.80 and 192.168.5.11 and is there a route between them without anything to stop traffic?
yes they can route and reach other just fine that’s how i see the INVITE from audiocodes in freepbx CLI and the sngrep. The call is inbound from audiocodes to freepbx as per original invite.
audiocodes is 10.10.10.80 as per user-agent, asterisk receives invite and does nothing with it., it’s not trying anything in any way. I had to enable debug 9 to see that it’s even attempting to match to a trunk which it kind of does. I’m not versed enough to understand that debug above
the calls from freepbx to audiocodes work fine using same trunk
this is a fresh one from sngrep drilled down with “enter”, shows up the same in the CLI. i masked the DIDs and CLID and nothing else
well I would classify this as a bug just because of the way asterisk does not respond.
I resolved the issue by removing the session expiry timers offered by audiocodes and asterisk now responds to INVITE
I’m not sure if they are invalid but the way asterisk just ignores the INVITE is the issue. If it replied with an error or anything it would be a lot easier to troubleshoot instead I had to modify every header to see what is going to make asterisk happy
Deleted these.
Session-Expires: 15;refresher=uac
Min-SE: 15
I think the Min-SE is RFC default to 90 if you don’t specify. Not sure about Session-Expires
I disagree with most of the others; this is very unlikely to be a networking issue; your first post shows that Asterisk not only got the INVITE, it planned to send a 100 Trying response:
But for a reason I don’t understand, it decided to delete the session before the response was actually sent. (We know that the response was not merely not logged, because Audiocodes kept retransmitting the INVITE.)
I suspect that the config is somehow corrupted, perhaps because of PHP version, but don’t know where to look.
What is the scope of the problem? I assume that it responds properly to INVITE from an extension, because you noted that outbound calls work, but please confirm that. Do you have any other trunks on the system, especially one using IP auth (Registration None and Authentication None)? Do those work properly? What is the Perimeta endpoint? Is it working?
I tried to compare your ‘core set debug 9’ with a similar system (FreePBX 15.0.17 Asterisk 16.19.0) with a similar trunk (Voxbeam). Results:
res_pjsip_endpoint_identifier_ip.c:255 ip_identify_match_check: Source address 10.10.10.80:5060 matches identify 'Audiocodes'
res_pjsip_endpoint_identifier_ip.c:288 common_identify: Identify 'Audiocodes' SIP message matched to endpoint Audiocodes
res_pjsip/pjsip_distributor.c:472 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000038 to use for Request msg INVITE/cseq=1 (rdata0x7fd4180187a8)
res_pjsip_session.c:3935 new_invite: Audiocodes
res_pjsip_session.c:4019 new_invite: Audiocodes: Call (UDP:10.10.10.80:5060) to extension '+1555123456' sending 100 Trying
res_pjsip_session.c:4334 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
res_pjsip_endpoint_identifier_ip.c: Source address 95.211.119.240:5060 matches identify 'Voxbeam-in2'
res_pjsip_endpoint_identifier_ip.c: Identify 'Voxbeam-in2' SIP message matched to endpoint Voxbeam-in2
res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003f to use for Request msg INVITE/cseq=1 (rdata0x7ff62c5ecb08)
res_pjsip_session.c: Voxbeam-in2
res_pjsip_session.c: Voxbeam-in2: Call (UDP:95.211.119.240:5060) to extension '44208077xxxx' sending 100 Trying
res_pjsip_session.c: Voxbeam-in2: Method is INVITE, Response is 100 Trying
res_pjsip_session.c: Voxbeam-in2
(entries from netsock2 related to setting up the response)
res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
So I believe that in res_pjsip_session.c, things went astray between lines 4019 and 4334. With luck, looking at the source will show what is wrong.
Sorry, I had not noticed your latest post about the session timers when I posted the comparison. However, it may still be useful for eventually pinpointing the bug.
Thanks for checking. The debug is hard to decipher but it makes a bit more sense now. Due to timers it was dropping just when it was going to do a 100trying or maybe due to some other mess in the code? I don’t know what it takes to trigger a “422 Session Interval Too Small” if that was the case but it should have, in my opinion
I’m reading the RFC and it’s full of “MAY” words when it talks about min-se and session-expires so it can be fully argued now.
I can also add that I installed a new distro from ISO SNG7-PBX16-64bit-2302-1 using asterisk 18 with same issue. however i restored a backup so if there was something corrupt in the config then it carried over
AFAICT, RFC4028 is current for this issue. I believe that the UAS (Asterisk in this case) must either accept the expiration specified in the INVITE, or reject the request with a 422. Just dropping the request as Asterisk did is IMO definitely a bug. At the Asterisk command prompt, typing pjsip show endpoint Audiocodes
will show the value of timers_min_se (90 on my system), so receiving session-expires of 15 should result in a 422.