ARI App stops receiving events abruptly

Asterisk Asterisk APIs
1

Hi, I am using the nodejs-ari-client to write an ARI app. I have used it multiple times earlier. I am facing a strange issue. My app abruptly stops receiving events for created channels. It gets the first Dial event for dialstatus=Down but doesn’t get any event after that like Ringing, Answered etc. Infact in asterisk console when I turn on ARI debug logs, I can see Asterisk is not sending these events to my app, although I can see on PJSIP traces the corresponding events arrive at Asterisk. I see a strange log in the full.log file “wants to happen in the future, stopping our traversal” which I have pasted at the end below. One thing I noticed is as soon as I run the app the CPU utilization peaks to 100% and load average goes up to 8-9 (its a small 2 core system). Could this be a CPU issue, I was assuming there would be no issue in running 2 calls on a 2 core 4 gb ec2 instance.

Following is my code:

/*jshint node:true*/
'use strict';

var ari = require('ari-client');
var util = require('util');

// ensure endpoint was passed in to script

ari.connect('http://localhost:12098', 'test123', 'tc_5549312', clientLoaded);

// handler for client being loaded
function clientLoaded (err, client) {
  if (err) {
    throw err;
  }

  // handler for StasisStart event
  function stasisStart(event, channel) {
    // ensure the channel is not a dialed channel
    var dialed = event.args[0] === 'dialed';

    if (!dialed) {
      channel.answer(function(err) {
        if (err) {
          throw err;
        }

        console.log('Channel %s has entered our application', channel.name);

        /*var playback = client.Playback();
        channel.play({media: 'sound:call-waiting'},
          playback, function(err, playback) {
            if (err) {
              throw err;
            }
        });*/

        originate(channel);
      });
    }
  }
  async function setVariable(channelId, variable, value){

    try {

        const setVariableResp = await client.channels.setChannelVar({
            channelId,
            variable,
            value
        });

        console.log(`Channel -> Setting variable, channel id: ${channelId}, variable: ${variable}, value: ${value}, response: ${setVariableResp}`);

    } catch (error) {

        throw error;

    }

  }
  async function originateExt() {
          const channelId = new Date().getTime();
    var channel = await client.channels.create({
            app:"xyz",
            appArgs:"ext",
            endpoint:"PJSIP/11001@sbc001",
            channelId
    });

    channel.on('Dial', function(event, dialed) {
            console.log(`Dial Event Received: ${JSON.stringify(event, 0, 1)}`);
            if (event.dialstatus == "ANSWER")
                    originate(channel);
    })
    channel.on('StasisStart', async function(event, dialed) {
      await setVariable(dialed.id, "CONNECTEDLINE(all)", "100002");
      //await dialed.dial();
      await client.channels.dial({channelId:dialed.id, timeout: -1});
    });

  }
  async function originate(channel) {
    var dialed = await client.channels.create({
            app:"xyz",
            appArgs:"dialed",
            endpoint:"PJSIP/11002@sbc001",
            originator: channel.id,
            channelId: `${channel.id}_d`
    });

    channel.on('StasisEnd', function(event, channel) {
      hangupDialed(channel, dialed);
    });

    dialed.on('ChannelDestroyed', function(event, dialed) {
      hangupOriginal(channel, dialed);
    });

    dialed.on('Dial', function(event, dialed) {
            console.log(`Dial Event Received: ${JSON.stringify(event, 0, 1)}`);
            if (event.dialstatus == "ANSWER")
                joinMixingBridge(channel, dialed);
    })
    dialed.on('StasisStart', async function(event, dialed) {
      await setVariable(dialed.id, "CONNECTEDLINE(all)", "+15752542760");
      await setVariable(dialed.id, "PJSIP_HEADER(add,P-Asserted-Identity)", "+15752542760");
      //await dialed.dial();
         await   client.channels.dial({channelId:dialed.id});
    });

  }

  // handler for original channel hanging up so we can gracefully hangup the
  // other end
  function hangupDialed(channel, dialed) {
    console.log(
      'Channel %s left our application, hanging up dialed channel %s',
      channel.name, dialed.name);

    // hangup the other end
    dialed.hangup(function(err) {
      // ignore error since dialed channel could have hung up, causing the
      // original channel to exit Stasis
    });
  }

  // handler for the dialed channel hanging up so we can gracefully hangup the
  // other end
  function hangupOriginal(channel, dialed) {
    console.log('Dialed channel %s has been hung up, hanging up channel %s',
      dialed.name, channel.name);

    // hangup the other end
    channel.hangup(function(err) {
      // ignore error since original channel could have hung up, causing the
      // dialed channel to exit Stasis
    });
  }

  // handler for dialed channel entering Stasis
  function joinMixingBridge(channel, dialed) {
    var bridge = client.Bridge();

    dialed.on('StasisEnd', function(event, dialed) {
      dialedExit(dialed, bridge);
    });

    dialed.answer(function(err) {
      if (err) {
        throw err;
      }
    });

    bridge.create({type: 'mixing'}, function(err, bridge) {
      if (err) {
        throw err;
      }

      console.log('Created bridge %s', bridge.id);

      addChannelsToBridge(channel, dialed, bridge);
    });
  }

  // handler for the dialed channel leaving Stasis
  function dialedExit(dialed, bridge) {
    console.log(
        'Dialed channel %s has left our application, destroying bridge %s',
        dialed.name, bridge.id);

    bridge.destroy(function(err) {
      if (err) {
        throw err;
      }
    });
  }

  // handler for new mixing bridge ready for channels to be added to it
  function addChannelsToBridge(channel, dialed, bridge) {
    console.log('Adding channel %s and dialed channel %s to bridge %s',
        channel.name, dialed.name, bridge.id);

    bridge.addChannel({channel: [channel.id, dialed.id]}, function(err) {
      if (err) {
        throw err;
      }
    });
  }

//  client.on('StasisStart', stasisStart);

  client.start('xyz');
  originateExt();
}

Following are the Logs from Asterisk Console after turning on ARI debug and PJSIP logging:

[Jun  5 17:40:08] <--- ARI request received from: 127.0.0.1:37992 --->
[Jun  5 17:40:08] Sec-WebSocket-Version: 13
[Jun  5 17:40:08] Sec-WebSocket-Key: /Qb+lDmoD/MDqnf7DnJLkA==
[Jun  5 17:40:08] Connection: Upgrade
[Jun  5 17:40:08] Upgrade: websocket
[Jun  5 17:40:08] Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
[Jun  5 17:40:08] Host: localhost:12098
[Jun  5 17:40:08] app: xyz
[Jun  5 17:40:08] api_key: test123:tc_5549312
[Jun  5 17:40:08] body:
[Jun  5 17:40:08]
[Jun  5 17:40:08]
[Jun  5 17:40:08]  Creating Stasis app 'xyz'
[Jun  5 17:40:08]   == WebSocket connection from '127.0.0.1:37992' for protocol '' accepted using version '13'
[Jun  5 17:40:08] <--- Sending ARI response to 127.0.0.1:37918 --->
[Jun  5 17:40:08] 200 OK
[Jun  5 17:40:08] Content-type: application/json
[Jun  5 17:40:08] {"id":"1717609208561","name":"PJSIP/sbc001-00000002","state":"Down","caller":{"name":"","number":""},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"in_router","exten":"s","priority":1,"app_name":"","app_data":""},"creationtime":"2024-06-05T17:40:08.584+0000","language":"en"}
[Jun  5 17:40:08]
[Jun  5 17:40:08] <--- Sending ARI event to 127.0.0.1:37992 --->
[Jun  5 17:40:08] {"type":"ChannelDialplan","timestamp":"2024-06-05T17:40:08.584+0000","dialplan_app":"Stasis","dialplan_app_data":"xyz,ext","channel":{"id":"1717609208561","name":"PJSIP/sbc001-00000002","state":"Down","caller":{"name":"","number":""},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"in_router","exten":"s","priority":1,"app_name":"Stasis","app_data":"xyz,ext"},"creationtime":"2024-06-05T17:40:08.584+0000","language":"en"},"asterisk_id":"0e:77:12:68:d4:e3","application":"xyz"}
[Jun  5 17:40:08] <--- Sending ARI event to 127.0.0.1:37992 --->
[Jun  5 17:40:08] {"variable":"STASISSTATUS","value":"","type":"ChannelVarset","timestamp":"2024-06-05T17:40:08.585+0000","channel":{"id":"1717609208561","name":"PJSIP/sbc001-00000002","state":"Down","caller":{"name":"","number":""},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"in_router","exten":"s","priority":1,"app_name":"Stasis","app_data":"xyz,ext"},"creationtime":"2024-06-05T17:40:08.584+0000","language":"en"},"asterisk_id":"0e:77:12:68:d4:e3","application":"xyz"}
[Jun  5 17:40:08] <--- Sending ARI event to 127.0.0.1:37992 --->
[Jun  5 17:40:08] {"type":"StasisStart","timestamp":"2024-06-05T17:40:08.585+0000","args":["ext"],"channel":{"id":"1717609208561","name":"PJSIP/sbc001-00000002","state":"Down","caller":{"name":"","number":""},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"in_router","exten":"s","priority":1,"app_name":"Stasis","app_data":"xyz,ext"},"creationtime":"2024-06-05T17:40:08.584+0000","language":"en"},"asterisk_id":"0e:77:12:68:d4:e3","application":"xyz"}
[Jun  5 17:40:08] <--- ARI request received from: 127.0.0.1:37918 --->
[Jun  5 17:40:08] user-agent: Shred
[Jun  5 17:40:08] Accept: application/json
[Jun  5 17:40:08] Authorization: Basic dGVzdDEyMzp0Y181NTQ5MzEy
[Jun  5 17:40:08] Host: localhost:12098
[Jun  5 17:40:08] Connection: keep-alive
[Jun  5 17:40:08] Content-Length: 0
[Jun  5 17:40:08] variable: CONNECTEDLINE(all)
[Jun  5 17:40:08] value: 100002
[Jun  5 17:40:08] body:
[Jun  5 17:40:08]
[Jun  5 17:40:08]
[Jun  5 17:40:08] <--- Sending ARI response to 127.0.0.1:37918 --->
[Jun  5 17:40:08] 204 No Content
[Jun  5 17:40:08]
[Jun  5 17:40:08]
[Jun  5 17:40:08] <--- Sending ARI event to 127.0.0.1:37992 --->
[Jun  5 17:40:08] {"type":"ChannelConnectedLine","timestamp":"2024-06-05T17:40:08.589+0000","channel":{"id":"1717609208561","name":"PJSIP/sbc001-00000002","state":"Down","caller":{"name":"","number":""},"connected":{"name":"","number":"100002"},"accountcode":"","dialplan":{"context":"in_router","exten":"s","priority":1,"app_name":"Stasis","app_data":"xyz,ext"},"creationtime":"2024-06-05T17:40:08.584+0000","language":"en"},"asterisk_id":"0e:77:12:68:d4:e3","application":"xyz"}
[Jun  5 17:40:08] <--- ARI request received from: 127.0.0.1:37918 --->
[Jun  5 17:40:08] user-agent: Shred
[Jun  5 17:40:08] Accept: application/json
[Jun  5 17:40:08] Authorization: Basic dGVzdDEyMzp0Y181NTQ5MzEy
[Jun  5 17:40:08] Host: localhost:12098
[Jun  5 17:40:08] Connection: keep-alive
[Jun  5 17:40:08] Content-Length: 0
[Jun  5 17:40:08] timeout: -1
[Jun  5 17:40:08] body:
[Jun  5 17:40:08]
[Jun  5 17:40:08]
[Jun  5 17:40:08] <--- Sending ARI response to 127.0.0.1:37918 --->
[Jun  5 17:40:08] 204 No Content
[Jun  5 17:40:08]
[Jun  5 17:40:08]
[Jun  5 17:40:08]     -- Channel PJSIP/sbc001-00000002 joined 'holding_bridge' stasis-bridge <014a71c0-4547-44f4-9bb9-3ed8d52650b0>
[Jun  5 17:40:08] <--- Sending ARI event to 127.0.0.1:37992 --->
[Jun  5 17:40:08] {"type":"Dial","timestamp":"2024-06-05T17:40:08.591+0000","dialstatus":"","forward":"","dialstring":"11001@sbc001","peer":{"id":"1717609208561","name":"PJSIP/sbc001-00000002","state":"Down","caller":{"name":"","number":""},"connected":{"name":"","number":"100002"},"accountcode":"","dialplan":{"context":"in_router","exten":"s","priority":1,"app_name":"Stasis","app_data":"xyz,ext"},"creationtime":"2024-06-05T17:40:08.584+0000","language":"en"},"asterisk_id":"0e:77:12:68:d4:e3","application":"xyz"}
[Jun  5 17:40:08] <--- Transmitting SIP request (1149 bytes) to UDP:10.52.13.195:5061 --->
[Jun  5 17:40:08] INVITE sip:11001@10.52.13.195:5061 SIP/2.0
[Jun  5 17:40:08] Via: SIP/2.0/UDP 10.52.13.26:5060;rport;branch=z9hG4bKPj763d5df9-b7c3-42d1-9665-4539302db9a8
[Jun  5 17:40:08] From: <sip:100002@10.52.13.26>;tag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a
[Jun  5 17:40:08] To: <sip:11001@10.52.13.195>
[Jun  5 17:40:08] Contact: <sip:asterisk@10.52.13.26:5060>
[Jun  5 17:40:08] Call-ID: cb4ec027-dba6-4d35-b2b2-b0b5664ec2c5
[Jun  5 17:40:08] CSeq: 22558 INVITE
[Jun  5 17:40:08] Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
[Jun  5 17:40:08] Supported: 100rel, timer, replaces, norefersub, histinfo
[Jun  5 17:40:08] Session-Expires: 1800
[Jun  5 17:40:08] Min-SE: 90
[Jun  5 17:40:08] P-Asserted-Identity: <sip:100002@10.52.13.26>
[Jun  5 17:40:08] Max-Forwards: 70
[Jun  5 17:40:08] User-Agent: Asterisk PBX certified-18.9-cert9
[Jun  5 17:40:08] Content-Type: application/sdp
[Jun  5 17:40:08] Content-Length:   427
[Jun  5 17:40:08]
[Jun  5 17:40:08] v=0
[Jun  5 17:40:08] o=- 2120345269 2120345269 IN IP4 10.52.13.26
[Jun  5 17:40:08] s=Asterisk
[Jun  5 17:40:08] c=IN IP4 10.52.13.26
[Jun  5 17:40:08] t=0 0
[Jun  5 17:40:08] m=audio 10122 RTP/AVP 0 8 101
[Jun  5 17:40:08] a=ice-ufrag:5d45463c789506e737e7de85297012cb
[Jun  5 17:40:08] a=ice-pwd:0cbb6a602659f4b220db508e5b0fbfa2
[Jun  5 17:40:08] a=candidate:Ha340d1a 1 UDP 2130706431 10.52.13.26 10122 typ host
[Jun  5 17:40:08] a=rtpmap:0 PCMU/8000
[Jun  5 17:40:08] a=rtpmap:8 PCMA/8000
[Jun  5 17:40:08] a=rtpmap:101 telephone-event/8000
[Jun  5 17:40:08] a=fmtp:101 0-16
[Jun  5 17:40:08] a=ptime:20
[Jun  5 17:40:08] a=maxptime:150
[Jun  5 17:40:08] a=sendrecv
[Jun  5 17:40:08] a=rtcp-mux
[Jun  5 17:40:08]
[Jun  5 17:40:08] <--- Received SIP response (404 bytes) from UDP:10.52.13.195:5061 --->
[Jun  5 17:40:08] SIP/2.0 100 trying -- your call is important to us
[Jun  5 17:40:08] Via: SIP/2.0/UDP 10.52.13.26:5060;rport=5060;branch=z9hG4bKPj763d5df9-b7c3-42d1-9665-4539302db9a8;received=10.52.13.26
[Jun  5 17:40:08] From: <sip:100002@10.52.13.26>;tag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a
[Jun  5 17:40:08] To: <sip:11001@10.52.13.195>
[Jun  5 17:40:08] Call-ID: cb4ec027-dba6-4d35-b2b2-b0b5664ec2c5
[Jun  5 17:40:08] CSeq: 22558 INVITE
[Jun  5 17:40:08] Server: kamailio (5.4.4 (x86_64/linux))
[Jun  5 17:40:08] Content-Length: 0
[Jun  5 17:40:08]
[Jun  5 17:40:08]
[Jun  5 17:40:08] <--- Received SIP response (681 bytes) from UDP:10.52.13.195:5061 --->
[Jun  5 17:40:08] SIP/2.0 180 Ringing
[Jun  5 17:40:08] Via: SIP/2.0/UDP 10.52.13.26:5060;received=10.52.13.26;rport=5060;branch=z9hG4bKPj763d5df9-b7c3-42d1-9665-4539302db9a8
[Jun  5 17:40:08] From: <sip:100002@10.52.13.26>;tag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a
[Jun  5 17:40:08] To: <sip:11001@10.52.13.195>;tag=kqa7up02s0
[Jun  5 17:40:08] CSeq: 22558 INVITE
[Jun  5 17:40:08] Call-ID: cb4ec027-dba6-4d35-b2b2-b0b5664ec2c5
[Jun  5 17:40:08] Supported: outbound
[Jun  5 17:40:08] User-Agent: SIP.js/0.21.2
[Jun  5 17:40:08] Record-Route: <sip:sbc-poc.brokerengage.net:8443;transport=ws;r2=on;lr=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:08] Record-Route: <sip:10.52.13.195:5061;r2=on;lr=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:08] Contact: <sip:24s0bgko@54.157.134.187:50422;transport=ws>
[Jun  5 17:40:08] Content-Length: 0
[Jun  5 17:40:08]
[Jun  5 17:40:08]
[Jun  5 17:40:08] <--- Sending ARI event to 127.0.0.1:37992 --->
[Jun  5 17:40:08] {"type":"ChannelStateChange","timestamp":"2024-06-05T17:40:08.881+0000","channel":{"id":"1717609208561","name":"PJSIP/sbc001-00000002","state":"Ringing","caller":{"name":"","number":""},"connected":{"name":"","number":"100002"},"accountcode":"","dialplan":{"context":"in_router","exten":"s","priority":1,"app_name":"Stasis","app_data":"xyz,ext"},"creationtime":"2024-06-05T17:40:08.584+0000","language":"en"},"asterisk_id":"0e:77:12:68:d4:e3","application":"xyz"}
[Jun  5 17:40:11] <--- Received SIP response (1224 bytes) from UDP:10.52.13.195:5061 --->
[Jun  5 17:40:11] SIP/2.0 200 OK
[Jun  5 17:40:11] Via: SIP/2.0/UDP 10.52.13.26:5060;received=10.52.13.26;rport=5060;branch=z9hG4bKPj763d5df9-b7c3-42d1-9665-4539302db9a8
[Jun  5 17:40:11] From: <sip:100002@10.52.13.26>;tag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a
[Jun  5 17:40:11] To: <sip:11001@10.52.13.195>;tag=kqa7up02s0
[Jun  5 17:40:11] CSeq: 22558 INVITE
[Jun  5 17:40:11] Call-ID: cb4ec027-dba6-4d35-b2b2-b0b5664ec2c5
[Jun  5 17:40:11] Supported: outbound
[Jun  5 17:40:11] User-Agent: SIP.js/0.21.2
[Jun  5 17:40:11] Record-Route: <sip:sbc-poc.brokerengage.net:8443;transport=ws;r2=on;lr=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:11] Record-Route: <sip:10.52.13.195:5061;r2=on;lr=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:11] Allow: ACK,BYE,CANCEL,INFO,INVITE,MESSAGE,NOTIFY,OPTIONS,PRACK,REFER,REGISTER,SUBSCRIBE
[Jun  5 17:40:11] Contact: <sip:24s0bgko@54.157.134.187:50422;transport=ws>
[Jun  5 17:40:11] Content-Type: application/sdp
[Jun  5 17:40:11] Content-Length: 426
[Jun  5 17:40:11]
[Jun  5 17:40:11] v=0
[Jun  5 17:40:11] o=- 4670309916855173072 2 IN IP4 10.52.13.195
[Jun  5 17:40:11] s=-
[Jun  5 17:40:11] t=0 0
[Jun  5 17:40:11] m=audio 10054 RTP/SAVPF 0 8 101
[Jun  5 17:40:11] c=IN IP4 10.52.13.195
[Jun  5 17:40:11] a=rtpmap:0 PCMU/8000
[Jun  5 17:40:11] a=rtpmap:8 PCMA/8000
[Jun  5 17:40:11] a=rtpmap:101 telephone-event/8000
[Jun  5 17:40:11] a=ssrc:1907629289 cname:XnSyG/KyfJuQnO/p
[Jun  5 17:40:11] a=sendrecv
[Jun  5 17:40:11] a=rtcp:10054
[Jun  5 17:40:11] a=rtcp-mux
[Jun  5 17:40:11] a=ptime:20
[Jun  5 17:40:11] a=ice-ufrag:S9E7Qqbv
[Jun  5 17:40:11] a=ice-pwd:xBQ6nvs9Mdj0XrrfWie61zdpR0
[Jun  5 17:40:11] a=candidate:O08pxpEEKWjZUKwM 1 UDP 2130706431 10.52.13.195 10054 typ host
[Jun  5 17:40:11]
[Jun  5 17:40:11]        > 0x7f0b980243e0 -- Strict RTP learning after remote address set to: 10.52.13.195:10054
[Jun  5 17:40:11] <--- Transmitting SIP request (630 bytes) to UDP:10.52.13.195:5061 --->
[Jun  5 17:40:11] ACK sip:24s0bgko@54.157.134.187:50422;transport=ws SIP/2.0
[Jun  5 17:40:11] Via: SIP/2.0/UDP 10.52.13.26:5060;rport;branch=z9hG4bKPj4af292d6-e35e-4c8c-97f6-2825c01c51af
[Jun  5 17:40:11] From: <sip:100002@10.52.13.26>;tag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a
[Jun  5 17:40:11] To: <sip:11001@10.52.13.195>;tag=kqa7up02s0
[Jun  5 17:40:11] Call-ID: cb4ec027-dba6-4d35-b2b2-b0b5664ec2c5
[Jun  5 17:40:11] CSeq: 22558 ACK
[Jun  5 17:40:11] Route: <sip:10.52.13.195:5061;lr;r2=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:11] Route: <sip:sbc-poc.brokerengage.net:8443;transport=ws;lr;r2=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:11] Max-Forwards: 70
[Jun  5 17:40:11] User-Agent: Asterisk PBX certified-18.9-cert9
[Jun  5 17:40:11] Content-Length:  0
[Jun  5 17:40:11]
[Jun  5 17:40:11]
[Jun  5 17:40:11] <--- Transmitting SIP request (1390 bytes) to UDP:10.52.13.195:5061 --->
[Jun  5 17:40:11] INVITE sip:24s0bgko@54.157.134.187:50422;transport=ws SIP/2.0
[Jun  5 17:40:11] Via: SIP/2.0/UDP 10.52.13.26:5060;rport;branch=z9hG4bKPj8d38712b-ed6f-42ea-8e18-1353ebb0c50e
[Jun  5 17:40:11] From: <sip:100002@10.52.13.26>;tag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a
[Jun  5 17:40:11] To: <sip:11001@10.52.13.195>;tag=kqa7up02s0
[Jun  5 17:40:11] Contact: <sip:asterisk@10.52.13.26:5060>
[Jun  5 17:40:11] Call-ID: cb4ec027-dba6-4d35-b2b2-b0b5664ec2c5
[Jun  5 17:40:11] CSeq: 22559 INVITE
[Jun  5 17:40:11] Route: <sip:10.52.13.195:5061;lr;r2=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:11] Route: <sip:sbc-poc.brokerengage.net:8443;transport=ws;lr;r2=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:11] Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
[Jun  5 17:40:11] Supported: 100rel, timer, replaces, norefersub, histinfo
[Jun  5 17:40:11] Session-Expires: 1800
[Jun  5 17:40:11] Min-SE: 90
[Jun  5 17:40:11] P-Asserted-Identity: <sip:100002@10.52.13.26>
[Jun  5 17:40:11] Max-Forwards: 70
[Jun  5 17:40:11] User-Agent: Asterisk PBX certified-18.9-cert9
[Jun  5 17:40:11] Content-Type: application/sdp
[Jun  5 17:40:11] Content-Length:   427
[Jun  5 17:40:11]
[Jun  5 17:40:11] v=0
[Jun  5 17:40:11] o=- 2120345269 2120345270 IN IP4 10.52.13.26
[Jun  5 17:40:11] s=Asterisk
[Jun  5 17:40:11] c=IN IP4 10.52.13.26
[Jun  5 17:40:11] t=0 0
[Jun  5 17:40:11] m=audio 10122 RTP/AVP 8 0 101
[Jun  5 17:40:11] a=ice-ufrag:5d45463c789506e737e7de85297012cb
[Jun  5 17:40:11] a=ice-pwd:0cbb6a602659f4b220db508e5b0fbfa2
[Jun  5 17:40:11] a=candidate:Ha340d1a 1 UDP 2130706431 10.52.13.26 10122 typ host
[Jun  5 17:40:11] a=rtpmap:8 PCMA/8000
[Jun  5 17:40:11] a=rtpmap:0 PCMU/8000
[Jun  5 17:40:11] a=rtpmap:101 telephone-event/8000
[Jun  5 17:40:11] a=fmtp:101 0-16
[Jun  5 17:40:11] a=ptime:20
[Jun  5 17:40:11] a=maxptime:150
[Jun  5 17:40:11] a=sendrecv
[Jun  5 17:40:11] a=rtcp-mux
[Jun  5 17:40:11]
[Jun  5 17:40:11] <--- Received SIP response (419 bytes) from UDP:10.52.13.195:5061 --->
[Jun  5 17:40:11] SIP/2.0 100 trying -- your call is important to us
[Jun  5 17:40:11] Via: SIP/2.0/UDP 10.52.13.26:5060;rport=5060;branch=z9hG4bKPj8d38712b-ed6f-42ea-8e18-1353ebb0c50e;received=10.52.13.26
[Jun  5 17:40:11] From: <sip:100002@10.52.13.26>;tag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a
[Jun  5 17:40:11] To: <sip:11001@10.52.13.195>;tag=kqa7up02s0
[Jun  5 17:40:11] Call-ID: cb4ec027-dba6-4d35-b2b2-b0b5664ec2c5
[Jun  5 17:40:11] CSeq: 22559 INVITE
[Jun  5 17:40:11] Server: kamailio (5.4.4 (x86_64/linux))
[Jun  5 17:40:11] Content-Length: 0
[Jun  5 17:40:11]
[Jun  5 17:40:11]
[Jun  5 17:40:11] <--- Received SIP response (998 bytes) from UDP:10.52.13.195:5061 --->
[Jun  5 17:40:11] SIP/2.0 200 OK
[Jun  5 17:40:11] Via: SIP/2.0/UDP 10.52.13.26:5060;received=10.52.13.26;rport=5060;branch=z9hG4bKPj8d38712b-ed6f-42ea-8e18-1353ebb0c50e
[Jun  5 17:40:11] From: <sip:100002@10.52.13.26>;tag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a
[Jun  5 17:40:11] To: <sip:11001@10.52.13.195>;tag=kqa7up02s0
[Jun  5 17:40:11] CSeq: 22559 INVITE
[Jun  5 17:40:11] Call-ID: cb4ec027-dba6-4d35-b2b2-b0b5664ec2c5
[Jun  5 17:40:11] Supported: outbound
[Jun  5 17:40:11] User-Agent: SIP.js/0.21.2
[Jun  5 17:40:11] Contact: <sip:24s0bgko@54.157.134.187:50422;transport=ws>
[Jun  5 17:40:11] Record-Route: <sip:sbc-poc.brokerengage.net:8443;transport=ws;r2=on;lr=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:11] Record-Route: <sip:10.52.13.195:5061;r2=on;lr=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:11] Content-Type: application/sdp
[Jun  5 17:40:11] Content-Length: 289
[Jun  5 17:40:11]
[Jun  5 17:40:11] v=0
[Jun  5 17:40:11] o=- 4670309916855173072 3 IN IP4 10.52.13.195
[Jun  5 17:40:11] s=-
[Jun  5 17:40:11] t=0 0
[Jun  5 17:40:11] m=audio 10054 RTP/AVP 8 0 101
[Jun  5 17:40:11] c=IN IP4 10.52.13.195
[Jun  5 17:40:11] a=rtpmap:8 PCMA/8000
[Jun  5 17:40:11] a=rtpmap:0 PCMU/8000
[Jun  5 17:40:11] a=rtpmap:101 telephone-event/8000
[Jun  5 17:40:11] a=ssrc:2075029358 cname:XnSyG/KyfJuQnO/p
[Jun  5 17:40:11] a=sendrecv
[Jun  5 17:40:11] a=rtcp:10054
[Jun  5 17:40:11] a=rtcp-mux
[Jun  5 17:40:11] a=ptime:20
[Jun  5 17:40:11]
[Jun  5 17:40:11] <--- Transmitting SIP request (630 bytes) to UDP:10.52.13.195:5061 --->
[Jun  5 17:40:11] ACK sip:24s0bgko@54.157.134.187:50422;transport=ws SIP/2.0
[Jun  5 17:40:11] Via: SIP/2.0/UDP 10.52.13.26:5060;rport;branch=z9hG4bKPj1b397262-a73a-40ba-be04-a2808b2fe498
[Jun  5 17:40:11] From: <sip:100002@10.52.13.26>;tag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a
[Jun  5 17:40:11] To: <sip:11001@10.52.13.195>;tag=kqa7up02s0
[Jun  5 17:40:11] Call-ID: cb4ec027-dba6-4d35-b2b2-b0b5664ec2c5
[Jun  5 17:40:11] CSeq: 22559 ACK
[Jun  5 17:40:11] Route: <sip:10.52.13.195:5061;lr;r2=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:11] Route: <sip:sbc-poc.brokerengage.net:8443;transport=ws;lr;r2=on;ftag=96ecf620-58a2-4e19-85fe-a3726b7e7a5a;nat=yes>
[Jun  5 17:40:11] Max-Forwards: 70
[Jun  5 17:40:11] User-Agent: Asterisk PBX certified-18.9-cert9
[Jun  5 17:40:11] Content-Length:  0
[Jun  5 17:40:11]
[Jun  5 17:40:11]
[Jun  5 17:40:13] <--- Received SIP request (379 bytes) from UDP:10.52.13.195:5061 --->
[Jun  5 17:40:13] OPTIONS sip:10.52.13.26 SIP/2.0
[Jun  5 17:40:13] Via: SIP/2.0/UDP 10.52.13.195:5061;branch=z9hG4bKe4a3.d59ab6b6000000000000000000000000.0
[Jun  5 17:40:13] To: <sip:10.52.13.26>
[Jun  5 17:40:13] From: <sip:kamailio1@speridian.com>;tag=ebe2200221527120c03a6c8ad31e2bb7-fcc699a9
[Jun  5 17:40:13] CSeq: 10 OPTIONS
[Jun  5 17:40:13] Call-ID: 370b638f319d0e74-1431184@10.52.13.195
[Jun  5 17:40:13] Max-Forwards: 70
[Jun  5 17:40:13] Content-Length: 0
[Jun  5 17:40:13] User-Agent: kamailio (5.4.4 (x86_64/linux))
[Jun  5 17:40:13]
[Jun  5 17:40:13]
[Jun  5 17:40:13] <--- Transmitting SIP response (901 bytes) to UDP:10.52.13.195:5061 --->
[Jun  5 17:40:13] SIP/2.0 200 OK
[Jun  5 17:40:13] Via: SIP/2.0/UDP 10.52.13.195:5061;received=10.52.13.195;branch=z9hG4bKe4a3.d59ab6b6000000000000000000000000.0
[Jun  5 17:40:13] Call-ID: 370b638f319d0e74-1431184@10.52.13.195
[Jun  5 17:40:13] From: <sip:kamailio1@speridian.com>;tag=ebe2200221527120c03a6c8ad31e2bb7-fcc699a9
[Jun  5 17:40:13] To: <sip:10.52.13.26>;tag=z9hG4bKe4a3.d59ab6b6000000000000000000000000.0
[Jun  5 17:40:13] CSeq: 10 OPTIONS
[Jun  5 17:40:13] Accept: application/sdp, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/simple-message-summary, application/dialog-info+xml, application/simple-message-summary, application/pidf+xml, application/dialog-info+xml, message/sipfrag;version=2.0
[Jun  5 17:40:13] Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
[Jun  5 17:40:13] Supported: 100rel, timer, replaces, norefersub
[Jun  5 17:40:13] Accept-Encoding: identity
[Jun  5 17:40:13] Accept-Language: en
[Jun  5 17:40:13] Server: Asterisk PBX certified-18.9-cert9
[Jun  5 17:40:13] Content-Length:  0
[Jun  5 17:40:13]
[Jun  5 17:40:13]
[Jun  5 17:40:19]        > 0x7f0b980243e0 -- Strict RTP learning after ICE completion
[Jun  5 17:40:20] <--- Transmitting SIP request (424 bytes) to UDP:10.52.13.195:5061 --->
[Jun  5 17:40:20] OPTIONS sip:10.52.13.195:5061 SIP/2.0
[Jun  5 17:40:20] Via: SIP/2.0/UDP 10.52.13.26:5060;rport;branch=z9hG4bKPj8a0de80c-ff50-4ba7-96f9-645ba40b0c8e
[Jun  5 17:40:20] From: <sip:sbc001@10.52.13.26>;tag=6bd5c0ce-1b7b-4270-b467-4ca7a00cbe69
[Jun  5 17:40:20] To: <sip:10.52.13.195>
[Jun  5 17:40:20] Contact: <sip:sbc001@10.52.13.26:5060>
[Jun  5 17:40:20] Call-ID: 4a8b04a5-e5d5-4b79-8c0b-f94de77b209f
[Jun  5 17:40:20] CSeq: 1698 OPTIONS
[Jun  5 17:40:20] Max-Forwards: 70
[Jun  5 17:40:20] User-Agent: Asterisk PBX certified-18.9-cert9
[Jun  5 17:40:20] Content-Length:  0
[Jun  5 17:40:20]
[Jun  5 17:40:20]
[Jun  5 17:40:20] <--- Received SIP response (424 bytes) from UDP:10.52.13.195:5061 --->
[Jun  5 17:40:20] SIP/2.0 484 Address Incomplete
[Jun  5 17:40:20] Via: SIP/2.0/UDP 10.52.13.26:5060;rport=5060;branch=z9hG4bKPj8a0de80c-ff50-4ba7-96f9-645ba40b0c8e;received=10.52.13.26
[Jun  5 17:40:20] From: <sip:sbc001@10.52.13.26>;tag=6bd5c0ce-1b7b-4270-b467-4ca7a00cbe69
[Jun  5 17:40:20] To: <sip:10.52.13.195>;tag=802559825c3fcaa37a7277409251c124.3a65f1bc
[Jun  5 17:40:20] Call-ID: 4a8b04a5-e5d5-4b79-8c0b-f94de77b209f
[Jun  5 17:40:20] CSeq: 1698 OPTIONS
[Jun  5 17:40:20] Server: kamailio (5.4.4 (x86_64/linux))
[Jun  5 17:40:20] Content-Length: 0
[Jun  5 17:40:20]
[Jun  5 17:40:20]
[Jun  5 17:40:23] <--- Received SIP request (379 bytes) from UDP:10.52.13.195:5061 --->
[Jun  5 17:40:23] OPTIONS sip:10.52.13.26 SIP/2.0
[Jun  5 17:40:23] Via: SIP/2.0/UDP 10.52.13.195:5061;branch=z9hG4bKf4a3.f682bd57000000000000000000000000.0
[Jun  5 17:40:23] To: <sip:10.52.13.26>
[Jun  5 17:40:23] From: <sip:kamailio1@speridian.com>;tag=ebe2200221527120c03a6c8ad31e2bb7-295c99a9
[Jun  5 17:40:23] CSeq: 10 OPTIONS
[Jun  5 17:40:23] Call-ID: 370b638f319d0e75-1431184@10.52.13.195
[Jun  5 17:40:23] Max-Forwards: 70
[Jun  5 17:40:23] Content-Length: 0
[Jun  5 17:40:23] User-Agent: kamailio (5.4.4 (x86_64/linux))
[Jun  5 17:40:23]
[Jun  5 17:40:23]
[Jun  5 17:40:23] <--- Transmitting SIP response (901 bytes) to UDP:10.52.13.195:5061 --->
[Jun  5 17:40:23] SIP/2.0 200 OK
[Jun  5 17:40:23] Via: SIP/2.0/UDP 10.52.13.195:5061;received=10.52.13.195;branch=z9hG4bKf4a3.f682bd57000000000000000000000000.0
[Jun  5 17:40:23] Call-ID: 370b638f319d0e75-1431184@10.52.13.195
[Jun  5 17:40:23] From: <sip:kamailio1@speridian.com>;tag=ebe2200221527120c03a6c8ad31e2bb7-295c99a9
[Jun  5 17:40:23] To: <sip:10.52.13.26>;tag=z9hG4bKf4a3.f682bd57000000000000000000000000.0
[Jun  5 17:40:23] CSeq: 10 OPTIONS
[Jun  5 17:40:23] Accept: application/sdp, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/simple-message-summary, application/dialog-info+xml, application/simple-message-summary, application/pidf+xml, application/dialog-info+xml, message/sipfrag;version=2.0
[Jun  5 17:40:23] Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
[Jun  5 17:40:23] Supported: 100rel, timer, replaces, norefersub
[Jun  5 17:40:23] Accept-Encoding: identity
[Jun  5 17:40:23] Accept-Language: en
[Jun  5 17:40:23] Server: Asterisk PBX certified-18.9-cert9
[Jun  5 17:40:23] Content-Length:  0
[Jun  5 17:40:23]
[Jun  5 17:40:23]
ip-10-52-13-26*CLI>

While following logs are coming when I enable core debug 3 in the full.log file.

[Jun  5 17:39:47] DEBUG[820746] bridge_channel.c: Hook 0x7f0b9c0158d8 on 0x7f0b9c018730(PJSIP/sbc001-00000000) wants to happen in the future, stopping our traversal
[Jun  5 17:39:47] DEBUG[820746] bridge_channel.c: Hook 0x7f0b9c0158d8 on 0x7f0b9c018730(PJSIP/sbc001-00000000) wants to happen in the future, stopping our traversal
[Jun  5 17:39:47] DEBUG[820746] bridge_channel.c: Hook 0x7f0b9c0158d8 on 0x7f0b9c018730(PJSIP/sbc001-00000000) wants to happen in the future, stopping our traversal
[Jun  5 17:39:47] DEBUG[820746] bridge_channel.c: Hook 0x7f0b9c0158d8 on 0x7f0b9c018730(PJSIP/sbc001-00000000) wants to happen in the future, stopping our traversal
[Jun  5 17:39:47] DEBUG[820746] bridge_channel.c: Hook 0x7f0b9c0158d8 on 0x7f0b9c018730(PJSIP/sbc001-00000000) wants to happen in the future, stopping our traversal
[Jun  5 17:39:47] DEBUG[820746] bridge_channel.c: Hook 0x7f0b9c0158d8 on 0x7f0b9c018730(PJSIP/sbc001-00000000) wants to happen in the future, stopping our traversal
2

Providing a subset of logging is rarely helpful, because it is your interpretation of what is relevant or useful. A complete log should always be provided. You also state 100% CPU usage, but what is actually the source of that?

3

Hi @jcolp , thankyou so much for the reply. I pasted subset of the logging as this is what kind of keeps on repeating in the logs. But let me share the entire logs here as attachments.
AsteriskCLI_CompleteLogs.txt (114.0 KB)
full.log.txt (125.3 KB)

CPU is being hogged by asterisk as it continuously prints those logs that you can see in full.log as soon as I stop asterisk CPU gets free. Also PJSIP channel is continuously shown in Ringing State and doesn’t hangup even after doing “channel request hangup all”.
I have tried asterisk 20.6.1, 20.8.1 LTS and 18.9-certified and issue is same.

image
image1441×504 206 KB

4

Here are my configurations:

http.conf

;[general]
;
; The name of the server, advertised in both the Server field in HTTP
; response message headers, as well as the <address /> element in certain HTTP
; response message bodies. If not furnished here, "Asterisk/{version}" will be
; used as a default value for the Server header field and the <address />
; element. Setting this property to a blank value will result in the omission
; of the Server header field from HTTP response message headers and the
; <address /> element from HTTP response message bodies.
;
servername=Asterisk
;
; Whether HTTP/HTTPS interface is enabled or not.  Default is no.
; This also affects manager/rawman/mxml access (see manager.conf)
;
enabled=yes
;
; Address to bind to, both for HTTP and HTTPS. You MUST specify
; a bindaddr in order for the HTTP server to run. There is no
; default value.
;
bindaddr=127.0.0.1
;
; Port to bind to for HTTP sessions (default is 8088)
;
bindport=12098
;
; Prefix allows you to specify a prefix for all requests
; to the server.  The default is blank.  If uncommented
; all requests must begin with /asterisk
;
;prefix=asterisk
;
; sessionlimit specifies the maximum number of httpsessions that will be
; allowed to exist at any given time. (default: 100)
;
sessionlimit=1000
;
; session_inactivity specifies the number of milliseconds to wait for
; more data over the HTTP connection before closing it.
;
; Default: 30000
session_inactivity=60000
;
; session_keep_alive specifies the number of milliseconds to wait for
; the next HTTP request over a persistent connection.
;
; Set to 0 to disable persistent HTTP connections.
; Default: 15000
session_keep_alive=30000

ari.conf

[general]
enabled = yes       ; When set to no, ARI support is disabled.
websocket_write_timeout = 500

[abccc]
type=user
read_only = no
password = abgccc
password_format = plain

[dddd]
type=user
read_only = no
password = 4334234
password_format = plain

ps_endpoints table:

Name                              |Value            |
----------------------------------+-----------------+
id                                |sbc001           |
transport                         |transport-udp    |
aors                              |sbc001           |
auth                              |                 |
context                           |in_router        |
disallow                          |all              |
allow                             |alaw,ulaw        |
direct_media                      |no               |
disable_direct_media_on_nat       |yes              |
dtmf_mode                         |rfc4733          |
external_media_address            |                 |
force_rport                       |no               |
ice_support                       |no               |
rewrite_contact                   |yes              |
rtp_ipv6                          |                 |
rtp_symmetric                     |yes              |
send_diversion                    |                 |
send_pai                          |yes              |
use_avpf                          |                 |
media_encryption                  |no               |
set_var                           |FROM_TRUNK=sbc001|
media_use_received_transport      |no               |
media_encryption_optimistic       |no               |
asymmetric_rtp_codec              |yes              |
rtcp_mux                          |yes              |
allow_overlap                     |yes              |
dtls_auto_generate_cert           |yes              |

pjsip.conf

;
; Basic UDP transport
;
[transport-udp]
type=transport
protocol=udp    ;udp,tcp,tls,ws,wss,flow
bind=10.52.13.26
;external_media_address=52.21.42.64
5

You would need to get a deadlock backtrace[1] to see the state of the system, and where it is potentially in a loop.

[1] Getting a Backtrace - Asterisk Documentation

6

Hi @jcolp I took these backtrace logs as you suggested at the time one of the channels were stuck and one of the cores was being used 100% by asterisk. Few more observations to add here:

  1. This issue only occurs on calls initiated via ARI, on calls that land on dialplan and are forwarded to another number there is no issue.
  2. I have all the calls routed through Kamailio and RTP Engine.

core-asterisk-running-2024-06-06T15-28-05Z-brief.txt (48.3 KB)
core-asterisk-running-2024-06-06T15-28-05Z-full.txt (219.2 KB)
core-asterisk-running-2024-06-06T15-28-05Z-info.txt (15.6 KB)
core-asterisk-running-2024-06-06T15-28-05Z-locks.txt (1.1 KB)
core-asterisk-running-2024-06-06T15-28-05Z-thread1.txt (1.7 KB)

7

Bridging is in a loop, why that is I don’t know. You would need to make an ARI application and set of configuration that can reproduce the issue and file an issue.

8

@jcolp I now tried to do the exact same thing without using nodejs-ari-client sdk, by direclty calling asterisk ARI apis via my node js app and using ws node module to listen to events, and there I don’t face this issue any more. The events are flowing properly and the CPU utilization is also normal.
Seems the bug is in nodejs-ari-client.

9

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.