ARI Originate Immediately Hanging Up

I just rebuilt my Asterisk server from the ground up and it all appears to be working just fine. Although I must have missed one config and for the life of me I can’t find it.

I’m issuing a channel originate command over ARI. Unfortunately the response back is a ChannelHangupRequest followed by a ChannelDestroyed.

Here’s the actual debug from ari set debug myapp on

<--- ARI request received from: [MY_ASTERISK_IP]:36280 --->
User-Agent: Mozilla
Accept-Language: en-US,en;q=0.5
Accept: application/json
Content-type: text/plain;charset=UTF-8
Host: [MY_ASTERISK_HOSTNAME]:8088
Connection: keep-alive
Content-Length: 0
endpoint: PJSIP/62441d1ded3d4027a3a8eea9236a258a
timeout: 60
callerId: Call with Test User
api_key: user:pass
app: myapp
body:
(null)

<--- Sending ARI response to [MY_ASTERISK_IP]:36280 --->
200 OK
Content-type: application/json
{
  "accountcode": "",
  "caller": {
    "name": "Call with Test User",
    "number": "unknown"
  },
  "connected": {
    "name": "Call with Test User",
    "number": ""
  },
  "creationtime": "2017-08-01T09:10:01.050+0000",
  "dialplan": {
    "context": "default",
    "exten": "s",
    "priority": 1
  },
  "id": "1501578601.0",
  "language": "en",
  "name": "PJSIP/62441d1ded3d4027a3a8eea9236a258a-00000000",
  "state": "Down"
}

<--- Sending ARI event to [MY_ASTERISK_IP]:1615 --->
{
  "application": "myapp",
  "asterisk_id": "0a:f2:47:14:0e:e0",
  "channel": {
    "accountcode": "",
    "caller": {
      "name": "Call with Test User",
      "number": "unknown"
    },
    "connected": {
      "name": "Call with Test User",
      "number": ""
    },
    "creationtime": "2017-08-01T09:10:01.050+0000",
    "dialplan": {
      "context": "default",
      "exten": "s",
      "priority": 1
    },
    "id": "1501578601.0",
    "language": "en",
    "name": "PJSIP/62441d1ded3d4027a3a8eea9236a258a-00000000",
    "state": "Down"
  },
  "timestamp": "2017-08-01T09:10:01.053+0000",
  "type": "ChannelHangupRequest"
}
<--- Sending ARI event to [MY_ASTERISK_IP]:1615 --->
{
  "application": "myapp",
  "asterisk_id": "0a:f2:47:14:0e:e0",
  "cause": 0,
  "cause_txt": "Unknown",
  "channel": {
    "accountcode": "",
    "caller": {
      "name": "Call with Test User",
      "number": "unknown"
    },
    "connected": {
      "name": "Call with Test User",
      "number": ""
    },
    "creationtime": "2017-08-01T09:10:01.050+0000",
    "dialplan": {
      "context": "default",
      "exten": "s",
      "priority": 1
    },
    "id": "1501578601.0",
    "language": "en",
    "name": "PJSIP/62441d1ded3d4027a3a8eea9236a258a-00000000",
    "state": "Down"
  },
  "timestamp": "2017-08-01T09:10:01.054+0000",
  "type": "ChannelDestroyed"
}

Also here is my extensions.conf file. I cleaned it all out just to have this in it but still no go…

[default]
 
exten => 1000,1,NoOp()
 same =>      n,Answer()
 same =>      n,Stasis(myapp)
 same =>      n,Hangup()

It’s as if it’s falling out of stasis and hanging up. There’s a couple other conf files that I could post but don’t want to blast everything at once. I’ve setup pjsip.conf, rtp.conf, and ari.conf. Can’t think of what other files to change. Welcome any insight or things I should check. Also I can post more conf files if that would help.

Configuration files for PJSIP would help, as well as Asterisk console output and “pjsip set logger on” output.

Here is pjsip.conf. Please note that pjsip_notify.conf and pjsip_wizard.conf have not been altered from the defaults from install. I’ve only touched the pjsip.conf file.

[0.0.0.0-udp]
type=transport
protocol=udp
bind=0.0.0.0:5060
external_media_address=[ASTERISK_EXTERNAL_IP]
external_signaling_address=[ASTERISK_EXTERNAL_IP]
allow_reload=yes
local_net=192.168.0.0/16

[0.0.0.0-tcp]
type=transport
protocol=tcp
bind=0.0.0.0:5061
external_media_address=[ASTERISK_EXTERNAL_IP]
external_signaling_address=[ASTERISK_EXTERNAL_IP]
allow_reload=yes
local_net=192.168.0.0/16

[0.0.0.0-tls]
type=transport
protocol=tls
bind=0.0.0.0:5161
external_media_address=[ASTERISK_EXTERNAL_IP]
external_signaling_address=[ASTERISK_EXTERNAL_IP]
cert_file=/etc/asterisk/keys/my.crt
priv_key_file=/etc/asterisk/keys/my.key
method=tlsv1
verify_client=no
verify_server=no
allow_reload=yes
local_net=192.168.0.0/16

And here is the output from pjsip set logger on…

PJSIP Logging enabled
<--- Received SIP request (754 bytes) from TLS:[MY_EXTERNAL_IP]:59887 --->
REGISTER sip:[ASTERISK_IP]:5161;transport=tls SIP/2.0
Via: SIP/2.0/TLS [MY_INTERNAL_IP]:51764;rport;branch=z9hG4bKPj94W2M.75PpldG2kSlRI4JeHLI9s2Zajd;alias
Max-Forwards: 70
From: <sip:62441d1ded3d4027a3a8eea9236a258a@[ASTERISK_IP]>;tag=7GduKMj9x1yWS0dDQqj5rSDRujnBDpTA
To: <sip:62441d1ded3d4027a3a8eea9236a258a@[ASTERISK_IP]>
Call-ID: flY12mlvKq7sPYhz6f8NqPsP6HdPBbK0
CSeq: 44943 REGISTER
User-Agent: Mozilla
Supported: outbound, path
Contact: <sip:62441d1ded3d4027a3a8eea9236a258a@[MY_INTERNAL_IP]:51764;transport=TLS;ob>;reg-id=1;+sip.instance="<urn:uuid:00000000-0000-0000-0000-00009c3fe9b2>"
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0


<--- Transmitting SIP response (631 bytes) to TLS:[MY_EXTERNAL_IP]:59887 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/TLS [MY_INTERNAL_IP]:51764;rport=59887;received=[MY_EXTERNAL_IP];branch=z9hG4bKPj94W2M.75PpldG2kSlRI4JeHLI9s2Zajd;alias
Call-ID: flY12mlvKq7sPYhz6f8NqPsP6HdPBbK0
From: <sip:62441d1ded3d4027a3a8eea9236a258a@[ASTERISK_IP]>;tag=7GduKMj9x1yWS0dDQqj5rSDRujnBDpTA
To: <sip:62441d1ded3d4027a3a8eea9236a258a@[ASTERISK_IP]>;tag=z9hG4bKPj94W2M.75PpldG2kSlRI4JeHLI9s2Zajd
CSeq: 44943 REGISTER
WWW-Authenticate: Digest  realm="asterisk",nonce="1501610140/c2fc61f9853e778ce51d6a2d0d3e0d0b",opaque="0dd579d5158f09e5",algorithm=md5,qop="auth"
Server: Asterisk PBX 13.17.0
Content-Length:  0


<--- Received SIP request (1091 bytes) from TLS:[MY_EXTERNAL_IP]:59887 --->
REGISTER sip:[ASTERISK_IP]:5161;transport=tls SIP/2.0
Via: SIP/2.0/TLS [MY_EXTERNAL_IP]:59887;rport;branch=z9hG4bKPj0gvp.QF-NUY9L7s148.2Wv5EgTdv4qn1;alias
Max-Forwards: 70
From: <sip:62441d1ded3d4027a3a8eea9236a258a@[ASTERISK_IP]>;tag=7GduKMj9x1yWS0dDQqj5rSDRujnBDpTA
To: <sip:62441d1ded3d4027a3a8eea9236a258a@[ASTERISK_IP]>
Call-ID: flY12mlvKq7sPYhz6f8NqPsP6HdPBbK0
CSeq: 44944 REGISTER
User-Agent: Mozilla
Supported: outbound, path
Contact: <sip:62441d1ded3d4027a3a8eea9236a258a@[MY_EXTERNAL_IP]:59887;transport=TLS;ob>;reg-id=1;+sip.instance="<urn:uuid:00000000-0000-0000-0000-00009c3fe9b2>"
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Authorization: Digest username="62441d1ded3d4027a3a8eea9236a258a", realm="asterisk", nonce="1501610140/c2fc61f9853e778ce51d6a2d0d3e0d0b", uri="sip:[ASTERISK_IP]:5161;transport=tls", response="da48bbe04e559fb0be073880aacd4f35", algorithm=md5, cnonce="tUW-S.NxV3qwIe6T34xPBGMOLA-t7otR", opaque="0dd579d5158f09e5", qop=auth, nc=00000001
Content-Length:  0


<--- Transmitting SIP response (637 bytes) to TLS:[MY_EXTERNAL_IP]:59887 --->
SIP/2.0 200 OK
Via: SIP/2.0/TLS [MY_EXTERNAL_IP]:59887;rport=59887;received=[MY_EXTERNAL_IP];branch=z9hG4bKPj0gvp.QF-NUY9L7s148.2Wv5EgTdv4qn1;alias
Call-ID: flY12mlvKq7sPYhz6f8NqPsP6HdPBbK0
From: <sip:62441d1ded3d4027a3a8eea9236a258a@[ASTERISK_IP]>;tag=7GduKMj9x1yWS0dDQqj5rSDRujnBDpTA
To: <sip:62441d1ded3d4027a3a8eea9236a258a@[ASTERISK_IP]>;tag=z9hG4bKPj0gvp.QF-NUY9L7s148.2Wv5EgTdv4qn1
CSeq: 44944 REGISTER
Date: Tue, 01 Aug 2017 17:55:40 GMT
Contact: <sip:62441d1ded3d4027a3a8eea9236a258a@[MY_EXTERNAL_IP]:59887;transport=TLS;ob>;expires=299
Expires: 300
Supported: path
Server: Asterisk PBX 13.17.0
Content-Length:  0


<--- ARI request received from: [MY_EXTERNAL_IP]:7429 --->
User-Agent: Mozilla
Accept-Language: en-US,en;q=0.5
Accept: application/json
Content-type: text/plain;charset=UTF-8
Host: [ASTERISK_IP]:8088
Connection: keep-alive
Content-Length: 0
endpoint: PJSIP/62441d1ded3d4027a3a8eea9236a258a
timeout: 60
callerId: Call with Test User
api_key: api:43678
app: myapp
body:
(null)

<--- Sending ARI response to [MY_EXTERNAL_IP]:7429 --->
200 OK
Content-type: application/json
{"language":"en","creationtime":"2017-08-01T17:55:40.889+0000","id":"1501610140.1","caller":{"name":"Call with Test User","number":"unknown"},"name":"PJSIP/62441d1ded3d4027a3a8eea9236a258a-00000001","state":"Down","connected":{"name":"Call with Test User","number":""},"accountcode":"","dialplan":{"priority":1,"context":"default","exten":"s"}}

<--- Sending ARI event to [MY_EXTERNAL_IP]:1615 --->
{"type":"ChannelHangupRequest","asterisk_id":"0a:f2:47:14:0e:e0","timestamp":"2017-08-01T17:55:40.922+0000","channel":{"language":"en","creationtime":"2017-08-01T17:55:40.889+0000","id":"1501610140.1","caller":{"name":"Call with Test User","number":"unknown"},"name":"PJSIP/62441d1ded3d4027a3a8eea9236a258a-00000001","state":"Down","connected":{"name":"Call with Test User","number":""},"accountcode":"","dialplan":{"priority":1,"context":"default","exten":"s"}},"application":"myapp"}
<--- Sending ARI event to [MY_EXTERNAL_IP]:1615 --->
{"cause_txt":"Unknown","type":"ChannelDestroyed","asterisk_id":"0a:f2:47:14:0e:e0","timestamp":"2017-08-01T17:55:40.923+0000","channel":{"language":"en","creationtime":"2017-08-01T17:55:40.889+0000","id":"1501610140.1","caller":{"name":"Call with Test User","number":"unknown"},"name":"PJSIP/62441d1ded3d4027a3a8eea9236a258a-00000001","state":"Down","connected":{"name":"Call with Test User","number":""},"accountcode":"","dialplan":{"priority":1,"context":"default","exten":"s"}},"cause":0,"application":"myapp"}

For reference my Asterisk is on a separate network with it’s own external IP. My ARI application is on a different network with it’s own external IP. However this setup works just fine with my old Asterisk server.

Thanks again for the help and taking a look at this. Very much appreciate your input. Let me know if there is anything else I could post that might help.

You don’t have an endpoint named “62441d1ded3d4027a3a8eea9236a258a” in the configuration provided. How is it configured?

Using ARI. I create the AOR, AUTH, and ENDPOINT dynamically using /asterisk/config/dynamic/…

Here’s the output from pjsip show endpoints…

pjsip show endpoints

 Endpoint:  <Endpoint/CID.....................................>  <State.....>  <Channels.>
    I/OAuth:  <AuthId/UserName...........................................................>
        Aor:  <Aor............................................>  <MaxContact>
      Contact:  <Aor/ContactUri..........................> <Hash....> <Status> <RTT(ms)..>
  Transport:  <TransportId........>  <Type>  <cos>  <tos>  <BindAddress..................>
   Identify:  <Identify/Endpoint.........................................................>
        Match:  <criteria.........................>
    Channel:  <ChannelId......................................>  <State.....>  <Time.....>
        Exten: <DialedExten...........>  CLCID: <ConnectedLineCID.......>
==========================================================================================

 Endpoint:  401f245dfc3b4e36bdb2064994e1d49f/unknown             Unavailable   0 of inf
     InAuth:  401f245dfc3b4e36bdb2064994e1d49f/401f245dfc3b4e36bdb2064994e1d49f
        Aor:  401f245dfc3b4e36bdb2064994e1d49f                   1
  Transport:  0.0.0.0-tls               tls      0      0  0.0.0.0:5161

 Endpoint:  62441d1ded3d4027a3a8eea9236a258a/unknown             Unavailable   0 of inf
     InAuth:  62441d1ded3d4027a3a8eea9236a258a/62441d1ded3d4027a3a8eea9236a258a
        Aor:  62441d1ded3d4027a3a8eea9236a258a                   1
  Transport:  0.0.0.0-tls               tls      0      0  0.0.0.0:5161

And what does the AOR look like?

pjsip show aors

      Aor:  <Aor..............................................>  <MaxContact>
    Contact:  <Aor/ContactUri............................> <Hash....> <Status> <RTT(ms)..>
==========================================================================================

      Aor:  401f245dfc3b4e36bdb2064994e1d49f                     1

      Aor:  62441d1ded3d4027a3a8eea9236a258a                     1

Just in case it’s needed… Here’s the detail on that aor…

pjsip show aor 62441d1ded3d4027a3a8eea9236a258a

      Aor:  <Aor..............................................>  <MaxContact>
    Contact:  <Aor/ContactUri............................> <Hash....> <Status> <RTT(ms)..>
==========================================================================================

      Aor:  62441d1ded3d4027a3a8eea9236a258a                     1


 ParameterName        : ParameterValue
 =====================================
 authenticate_qualify : false
 contact              : 
 default_expiration   : 3600
 mailboxes            : 
 max_contacts         : 1
 maximum_expiration   : 7200
 minimum_expiration   : 60
 outbound_proxy       : 
 qualify_frequency    : 0
 qualify_timeout      : 3.000000
 remove_existing      : true
 support_path         : true
 voicemail_extension  : 

There doesn’t appear to be any contact on it from what I can see, so there’s no location information for where to send the call.

I’m only using these to call out from the asterisk server to the sip client. The SIP client never initiates a call.

What I did just notice is the on the server that does work, the AOR and ENDPOINT are listed twice for some reason. But on this new server it’s listed only once. Not sure why.

Here’s what the AOR looks like on the working Asterisk server…

pjsip show aors

      Aor:  <Aor..............................................>  <MaxContact>
    Contact:  <Aor/ContactUri............................> <Hash....> <Status> <RTT(ms)..>
==========================================================================================

      Aor:  401f245dfc3b4e36bdb2064994e1d49f                     1

      Aor:  401f245dfc3b4e36bdb2064994e1d49f                     1

      Aor:  62441d1ded3d4027a3a8eea9236a258a                     1

      Aor:  62441d1ded3d4027a3a8eea9236a258a                     1

  
ip-[ASTERISK_INTERNAL_IP]*CLI> pjsip show aor 62441d1ded3d4027a3a8eea9236a258a

      Aor:  <Aor..............................................>  <MaxContact>
    Contact:  <Aor/ContactUri............................> <Hash....> <Status> <RTT(ms)..>
==========================================================================================

      Aor:  62441d1ded3d4027a3a8eea9236a258a                     1


 ParameterName        : ParameterValue
 =====================================
 authenticate_qualify : false
 contact              : 
 default_expiration   : 3600
 mailboxes            : 
 max_contacts         : 1
 maximum_expiration   : 7200
 minimum_expiration   : 60
 outbound_proxy       : 
 qualify_frequency    : 0
 qualify_timeout      : 3.000000
 remove_existing      : true
 support_path         : true
 voicemail_extension  : 

It could be there twice if it was stored in multiple backends, and not just pushed in. This could also allow it to work if the contact was persisted there instead. As it is your problem isn’t ARI, it’s your PJSIP setup. The contact isn’t getting stored (how are you storing contacts) so the endpoint can’t be called.

So I do set the contact if it’s a SIP trunk for making calls from asterisk to a real phone number. But for the sip clients themselves I don’t set the contact. This seems to work on the old server. Again I just call out from Asterisk and then I add that channel to a bridge. Not sure if that makes a difference.

Also I wipe out all the endpoints/aors/auths from the server each time I restart my ARI application. Then I rebuild those I need. So I don’t think it’s stored anywhere.

If this shouldn’t work without setting the contact for a sip client. I’m not sure how this has ever worked on the old server. There must be one more piece missing. Would looking at my sorcery.conf file shed any light?

If it’s a SIP trunk then you explicitly provide a contact with the information of the upstream server to use. For clients themselves they register and add a contact to the AOR and keep it refreshed. Providing the sorcery.conf can shed some light. I’d strongly suggest not complicating things with push configuration until you understand how to configure Asterisk via configuration files first though, or else you greatly complicate things and make it hard to debug unless you know precisely what you are doing.

Apologies. The AOR contact DOES get filled out. When I grabbed the AOR before my device was not registered… Here it is registered.

pjsip show aor 62441d1ded3d4027a3a8eea9236a258a

      Aor:  <Aor..............................................>  <MaxContact>
    Contact:  <Aor/ContactUri............................> <Hash....> <Status> <RTT(ms)..>
==========================================================================================

      Aor:  62441d1ded3d4027a3a8eea9236a258a                     1
    Contact:  62441d1ded3d4027a3a8eea9236a258a/sip:62441d1 7f1c50be50 Unknown         nan


 ParameterName        : ParameterValue
 ===============================================================================================
 authenticate_qualify : false
 contact              : sip:62441d1ded3d4027a3a8eea9236a258a@[MY EXTERNAL IP]:48655;transport=TLS;ob
 default_expiration   : 3600
 mailboxes            : 
 max_contacts         : 1
 maximum_expiration   : 7200
 minimum_expiration   : 60
 outbound_proxy       : 
 qualify_frequency    : 0
 qualify_timeout      : 3.000000
 remove_existing      : true
 support_path         : true
 voicemail_extension  : 

And calling now fails? Is there anything else on the console?

Unfortunately no. That’s all there was in the console. My sip client only registers for 30 seconds and then unregisters (think mobile device to save battery). So that’s why I missed the AOR contact before. I just did another test and confirmed that the AOR was registered before the invite went out and remained so through the SIP conversation. But still the same result.

You can try sending debug to console in logger.conf and bumping up the debug level using “core set debug 9”, it may provide further information. As this is just getting more and more complicated that’s really all I can offer on trying to figure out what is going on.

Here’s my sorcery.conf file in case it may shed any light. Its exactly the same as the working server…

[test_sorcery_section]
test=memory

[test_sorcery_cache]
test/cache=test
test=memory

[res_pjsip]                                                                                                                                                        
endpoint=astdb,ps_endpoints
auth=astdb,ps_auths
aor=astdb,ps_aors
domain_alias=astdb,ps_domain_aliases
contact=astdb,ps_contacts
system=astdb,ps_systems
 
[res_pjsip_endpoint_identifier_ip]
identify=astdb,ps_endpoint_id_ips
 
[res_pjsip_outbound_registration]
registration=astdb,ps_registrations

Ok no problem. I appreciate the help so far. I’ll keep digging in and hopefully when I figure this out I’ll let you know. I’m betting it’s just an errant config somewhere.

Finally figured it out.

Your suggestion of setting the debug to console and going to debug 9 helped. I found this line in the output…

[Aug  1 20:33:53] DEBUG[4574]: sdp_srtp.c:53 ast_sdp_srtp_alloc: No SRTP module loaded, can't setup SRTP session.

Turns out I didn’t have the SRTP module installed. Which was an issue from before the install. Needed to get that lib installed and then rebuild asterisk. It’s up and working now.

Thanks again!