FreePBX and non-FreePBX trunk, incoming to FreePBX works, outgoing does not

FreePBX Installation / Upgrade
1

I am trying to configure a trunk between two SIP systems with no authentication on either side. Calls into FreePBX are working but calls outbound from FreePBX are not. A tcpdump shows that the FreePBX system is not sending any ethernet frame at all to the other SIP system. I also never see SIP OPTIONS between the systems, but not sure if I should expect that in this case. I have an outbound route setup pointing to the correct trunk with a dialplan of 3XXX, which seems to work correctly because when I dial 3666 it in fact tries to use the CIC_Trunk.

Logged errors are:

[2018-10-11 19:18:38] ERROR[30257]: res_pjsip.c:3237 ast_sip_create_dialog_uac: Endpoint 'CIC_Trunk': Could not create dialog to invalid URI 'CIC_Trunk'.  Is endpoint registered and reachable?
[2018-10-11 19:18:38] ERROR[30257]: chan_pjsip.c:2487 request: Failed to create outgoing session to endpoint 'CIC_Trunk'
[2018-10-11 19:18:38] WARNING[25178][C-00000043]: app_dial.c:2512 dial_exec_full: Unable to create channel of type 'PJSIP' (cause 3 - No route to destination)

System versions:
Current PBX Version: 14.0.3.19
Current System Version: 12.7.5-1807-1.sng7

Please let me know what other info I can provide to help me understand and resolve this.

2

Show your trunk settings and a pjsip logger output of an actual call attempt.

3

Which file do you need me to share? I will get the logger output shortly.

While preparing to collect log info I noticed the following. I would have expected during this time to see some traffic on the wire between FreePBX and CIC (other SIP server)

[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip/pjsip_options.c:926 sip_options_qualify_aor: Qualifying all contacts on AOR 'CIC_Trunk'
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip/pjsip_options.c:856 sip_options_qualify_contact: Qualifying contact 'CIC_Trunk@@fc5b628876d2fb8f938d656baa6a7cde' on AOR 'CIC_Trunk'
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip.c:3983 endpt_send_request: 0x7fc8d43163a8: Wrapper created
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip.c:3998 endpt_send_request: 0x7fc8d43163a8: Set timer to 3000 msec
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target 'cmp02-cic01'
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target 'cmp02-cic01' is 'UDP'
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip/pjsip_resolver.c:547 sip_resolve: [0x7fc8d4310c80] Created resolution tracking for target 'cmp02-cic01'
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip/pjsip_resolver.c:177 sip_resolve_add: [0x7fc8d4310c80] Added target 'cmp02-cic01' with record type '1', transport 'UDP', and port '5060'
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip/pjsip_resolver.c:616 sip_resolve: [0x7fc8d4310c80] Starting initial resolution using parallel queries for target 'cmp02-cic01'
[2018-10-12 06:56:21] DEBUG[14821]: res_pjsip/pjsip_resolver.c:277 sip_resolve_callback: [0x7fc8d4310c80] All parallel queries completed
[2018-10-12 06:56:21] DEBUG[14821]: res_pjsip/pjsip_resolver.c:419 sip_resolve_callback: [0x7fc8d4310c80] Resolution completed - 0 viable targets
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip/pjsip_resolver.c:207 sip_resolve_invoke_user_callback: [0x7fc8d4310c80] Invoking user callback with '0' addresses
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip.c:3861 endpt_send_request_cb: 0x7fc8d43163a8: PJSIP tsx response received
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip.c:3874 endpt_send_request_cb: 0x7fc8d43163a8: Cancelling timer
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip.c:3883 endpt_send_request_cb: 0x7fc8d43163a8: Timer cancelled
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip.c:3904 endpt_send_request_cb: 0x7fc8d43163a8: Callbacks executed
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip.c:3960 send_request_wrapper_destructor: 0x7fc8d43163a8: wrapper destroyed
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip/pjsip_options.c:758 sip_options_contact_status_notify_task: Contact CIC_Trunk/sip:cmp02-cic01:5060 status didn't change: Unreachable, RTT: 0.000 msec
[2018-10-12 06:56:21] DEBUG[14795]: res_pjsip/pjsip_options.c:776 sip_options_contact_status_notify_task: AOR 'CIC_Trunk' now has 0 available contacts
4

Screenshots of your PJSIP trunk settings. An example call from the Asterisk Console with the psjip logger on…

5

Below are the screenshots and logs during an attempted call.

Screenshot%20from%202018-10-12%2008-59-12
Screenshot%20from%202018-10-12%2008-59-121182×534 39.4 KB

Screenshot%20from%202018-10-12%2008-59-30
Screenshot%20from%202018-10-12%2008-59-301125×538 41.6 KB 

<--- Received SIP request (970 bytes) from UDP:172.19.12.116:5060 --->
INVITE sip:[email protected];user=phone SIP/2.0
Via: SIP/2.0/UDP 172.19.12.116;branch=z9hG4bKce84d1003E77B5C7
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>
CSeq: 1 INVITE
Call-ID: [email protected]
Contact: <sip:[email protected]>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomVVX-VVX_311-UA/5.4.5.8201
Accept-Language: en
Supported: replaces,100rel
Allow-Events: conference,talk,hold
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 352

v=0
o=- 1539358599 1539358599 IN IP4 172.19.12.116
s=Polycom IP Phone
c=IN IP4 172.19.12.116
t=0 0
a=sendrecv
m=audio 2248 RTP/AVP 9 102 0 8 18 127
a=rtpmap:9 G722/8000
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=32000
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

<--- Transmitting SIP response (521 bytes) to UDP:172.19.12.116:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 172.19.12.116;rport=5060;received=172.19.12.116;branch=z9hG4bKce84d1003E77B5C7
Call-ID: [email protected]
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>;tag=z9hG4bKce84d1003E77B5C7
CSeq: 1 INVITE
WWW-Authenticate: Digest  realm="asterisk",nonce="1539358600/e5e82cdb410b8e97d08580dc176610d8",opaque="4858559f62da2599",algorithm=md5,qop="auth"
Server: FPBX-14.0.3.19(15.5.0)
Content-Length:  0


<--- Received SIP request (543 bytes) from UDP:172.19.12.116:5060 --->
ACK sip:[email protected];user=phone SIP/2.0
Via: SIP/2.0/UDP 172.19.12.116;branch=z9hG4bKce84d1003E77B5C7
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>;tag=z9hG4bKce84d1003E77B5C7
CSeq: 1 ACK
Call-ID: [email protected]
Contact: <sip:[email protected]>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomVVX-VVX_311-UA/5.4.5.8201
Accept-Language: en
Max-Forwards: 70
Content-Length: 0


<--- Received SIP request (1257 bytes) from UDP:172.19.12.116:5060 --->
INVITE sip:[email protected];user=phone SIP/2.0
Via: SIP/2.0/UDP 172.19.12.116;branch=z9hG4bK7715953b1D8A0CFE
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>
CSeq: 2 INVITE
Call-ID: [email protected]
Contact: <sip:[email protected]>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomVVX-VVX_311-UA/5.4.5.8201
Accept-Language: en
Supported: replaces,100rel
Allow-Events: conference,talk,hold
Authorization: Digest username="3065", realm="asterisk", nonce="1539358600/e5e82cdb410b8e97d08580dc176610d8", qop=auth, cnonce="5ytzULxhgvpKs4p", nc=00000001, opaque="4858559f62da2599", uri="sip:[email protected];user=phone", response="a38ff2ecf25ca58f941b179ec36a9935", algorithm=MD5
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 352

v=0
o=- 1539358599 1539358599 IN IP4 172.19.12.116
s=Polycom IP Phone
c=IN IP4 172.19.12.116
t=0 0
a=sendrecv
m=audio 2248 RTP/AVP 9 102 0 8 18 127
a=rtpmap:9 G722/8000
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=32000
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

<--- Transmitting SIP response (340 bytes) to UDP:172.19.12.116:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.19.12.116;rport=5060;received=172.19.12.116;branch=z9hG4bK7715953b1D8A0CFE
Call-ID: [email protected]
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>
CSeq: 2 INVITE
Server: FPBX-14.0.3.19(15.5.0)
Content-Length:  0


[2018-10-12 10:36:40] ERROR[18744]: res_pjsip.c:3295 ast_sip_create_dialog_uac: Endpoint 'CIC': Could not create dialog to invalid URI 'CIC'.  Is endpoint registered and reachable?
[2018-10-12 10:36:40] ERROR[18744]: chan_pjsip.c:2497 request: Failed to create outgoing session to endpoint 'CIC'
[2018-10-12 10:36:40] WARNING[22252][C-0000000e]: app_dial.c:2512 dial_exec_full: Unable to create channel of type 'PJSIP' (cause 3 - No route to destination)
<--- Transmitting SIP response (927 bytes) to UDP:172.19.12.116:5060 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 172.19.12.116;rport=5060;received=172.19.12.116;branch=z9hG4bK7715953b1D8A0CFE
Call-ID: [email protected]
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>;tag=4fcac243-6dae-499a-b762-47189915b4c0
CSeq: 2 INVITE
Server: FPBX-14.0.3.19(15.5.0)
Contact: <sip:172.19.11.206:5060>
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
P-Asserted-Identity: "CID:3065" <sip:[email protected];user=phone>
Content-Type: application/sdp
Content-Length:   287

v=0
o=- 1539358599 1539358601 IN IP4 172.19.11.206
s=Asterisk
c=IN IP4 172.19.11.206
t=0 0
m=audio 18424 RTP/AVP 0 8 9 127
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:127 telephone-event/8000
a=fmtp:127 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
6

This is not the full call. This is the Polycom calling the PBX part of the call. Where is the PBX’s attempt to call the provider? That is the part where the call is failing.

7

Unless you are very comfortable reading SIP transactions, then ‘sngrep’ run from bash (or “!sngrep” from the asterisk CLI) is likely a more understandable view of how SIP is working, isolated to individual connections and drill-able down to the same detail when necessary. Try it :slight_smile:

1 Like
8

I’m not sure how I failed to paste the full log the first time, here is a second attempt.

<--- Received SIP request (970 bytes) from UDP:172.19.12.116:5060 --->
INVITE sip:[email protected];user=phone SIP/2.0
Via: SIP/2.0/UDP 172.19.12.116;branch=z9hG4bKce84d1003E77B5C7
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>
CSeq: 1 INVITE
Call-ID: [email protected]
Contact: <sip:[email protected]>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomVVX-VVX_311-UA/5.4.5.8201
Accept-Language: en
Supported: replaces,100rel
Allow-Events: conference,talk,hold
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 352

v=0
o=- 1539358599 1539358599 IN IP4 172.19.12.116
s=Polycom IP Phone
c=IN IP4 172.19.12.116
t=0 0
a=sendrecv
m=audio 2248 RTP/AVP 9 102 0 8 18 127
a=rtpmap:9 G722/8000
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=32000
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

<--- Transmitting SIP response (521 bytes) to UDP:172.19.12.116:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 172.19.12.116;rport=5060;received=172.19.12.116;branch=z9hG4bKce84d1003E77B5C7
Call-ID: [email protected]
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>;tag=z9hG4bKce84d1003E77B5C7
CSeq: 1 INVITE
WWW-Authenticate: Digest  realm="asterisk",nonce="1539358600/e5e82cdb410b8e97d08580dc176610d8",opaque="4858559f62da2599",algorithm=md5,qop="auth"
Server: FPBX-14.0.3.19(15.5.0)
Content-Length:  0


<--- Received SIP request (543 bytes) from UDP:172.19.12.116:5060 --->
ACK sip:[email protected];user=phone SIP/2.0
Via: SIP/2.0/UDP 172.19.12.116;branch=z9hG4bKce84d1003E77B5C7
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>;tag=z9hG4bKce84d1003E77B5C7
CSeq: 1 ACK
Call-ID: [email protected]
Contact: <sip:[email protected]>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomVVX-VVX_311-UA/5.4.5.8201
Accept-Language: en
Max-Forwards: 70
Content-Length: 0


<--- Received SIP request (1257 bytes) from UDP:172.19.12.116:5060 --->
INVITE sip:[email protected];user=phone SIP/2.0
Via: SIP/2.0/UDP 172.19.12.116;branch=z9hG4bK7715953b1D8A0CFE
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>
CSeq: 2 INVITE
Call-ID: [email protected]
Contact: <sip:[email protected]>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomVVX-VVX_311-UA/5.4.5.8201
Accept-Language: en
Supported: replaces,100rel
Allow-Events: conference,talk,hold
Authorization: Digest username="3065", realm="asterisk", nonce="1539358600/e5e82cdb410b8e97d08580dc176610d8", qop=auth, cnonce="5ytzULxhgvpKs4p", nc=00000001, opaque="4858559f62da2599", uri="sip:[email protected];user=phone", response="a38ff2ecf25ca58f941b179ec36a9935", algorithm=MD5
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 352

v=0
o=- 1539358599 1539358599 IN IP4 172.19.12.116
s=Polycom IP Phone
c=IN IP4 172.19.12.116
t=0 0
a=sendrecv
m=audio 2248 RTP/AVP 9 102 0 8 18 127
a=rtpmap:9 G722/8000
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=32000
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

<--- Transmitting SIP response (340 bytes) to UDP:172.19.12.116:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.19.12.116;rport=5060;received=172.19.12.116;branch=z9hG4bK7715953b1D8A0CFE
Call-ID: [email protected]
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>
CSeq: 2 INVITE
Server: FPBX-14.0.3.19(15.5.0)
Content-Length:  0


[2018-10-12 10:36:40] ERROR[18744]: res_pjsip.c:3295 ast_sip_create_dialog_uac: Endpoint 'CIC': Could not create dialog to invalid URI 'CIC'.  Is endpoint registered and reachable?
[2018-10-12 10:36:40] ERROR[18744]: chan_pjsip.c:2497 request: Failed to create outgoing session to endpoint 'CIC'
[2018-10-12 10:36:40] WARNING[22252][C-0000000e]: app_dial.c:2512 dial_exec_full: Unable to create channel of type 'PJSIP' (cause 3 - No route to destination)
<--- Transmitting SIP response (927 bytes) to UDP:172.19.12.116:5060 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 172.19.12.116;rport=5060;received=172.19.12.116;branch=z9hG4bK7715953b1D8A0CFE
Call-ID: [email protected]
From: "3065" <sip:[email protected]>;tag=328613B6-709D3375
To: <sip:[email protected];user=phone>;tag=4fcac243-6dae-499a-b762-47189915b4c0
CSeq: 2 INVITE
Server: FPBX-14.0.3.19(15.5.0)
Contact: <sip:172.19.11.206:5060>
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
P-Asserted-Identity: "CID:3065" <sip:[email protected];user=phone>
Content-Type: application/sdp
Content-Length:   287

v=0
o=- 1539358599 1539358601 IN IP4 172.19.11.206
s=Asterisk
c=IN IP4 172.19.11.206
t=0 0
m=audio 18424 RTP/AVP 0 8 9 127
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:127 telephone-event/8000
a=fmtp:127 0-16
a=ptime:20
a=maxptime:150
a=sendrecv