fix and test cases for #217 - sip:refer blocks if NOTIFY not received after 202 Accepted (#218)

* further fix for race condition in #206

* #206: ignore request to start bot mode when bot mode is already active

.github/workflows/build.yml

@@ -1,7 +1,6 @@
 name: CI
 
-on:
-  push:
+on: [push, pull_request]
 
 jobs:
   build:
@@ -20,3 +19,5 @@ jobs:
           AWS_ACCESS_KEY_ID: ${{ secrets.AWS_ACCESS_KEY_ID }}
           AWS_SECRET_ACCESS_KEY: ${{ secrets.AWS_SECRET_ACCESS_KEY }}
           AWS_REGION: ${{ secrets.AWS_REGION }}
+          MICROSOFT_REGION: ${{ secrets.MICROSOFT_REGION }}
+          MICROSOFT_API_KEY: ${{ secrets.MICROSOFT_API_KEY }}

lib/session/call-session.js

@@ -449,6 +449,10 @@ class CallSession extends Emitter {
 
   async enableBotMode(gather, autoEnable) {
     try {
+      if (this.backgroundGatherTask) {
+        this.logger.info('CallSession:enableBotMode - bot mode currently enabled, ignoring request to start again');
+        return;
+      }
       const t = normalizeJambones(this.logger, [gather]);
       this.backgroundGatherTask = makeTask(this.logger, t[0]);
       this._bargeInEnabled = true;

lib/tasks/gather.js

@@ -191,6 +191,10 @@ class TaskGather extends Task {
       if (this.input.includes('speech') && !this.listenDuringPrompt) {
         this._initSpeech(cs, ep)
           .then(() => {
+            if (this.killed) {
+              this.logger.info('Gather:exec - task was quickly killed so do not transcribe');
+              return;
+            }
             this._startTranscribing(ep);
             return updateSpeechCredentialLastUsed(this.sttCredentials.speech_credential_sid);
           })
@@ -223,7 +227,13 @@ class TaskGather extends Task {
           if (!this.killed) startListening(cs, ep);
         });
       }
-      else startListening(cs, ep);
+      else {
+        if (this.killed) {
+          this.logger.info('Gather:exec - task was immediately killed so do not transcribe');
+          return;
+        }
+        startListening(cs, ep);
+      }
 
       if (this.input.includes('speech') && this.listenDuringPrompt) {
         await this._initSpeech(cs, ep);

lib/tasks/sip_refer.js

@@ -47,7 +47,17 @@ class TaskSipRefer extends Task {
 
       /* if we fail, fall through to next verb.  If success, we should get BYE from far end */
       if (this.referStatus === 202) {
+        this._notifyTimer = setTimeout(() => {
+          this.logger.info('TaskSipRefer:exec - no NOTIFY received in 15 secs, exiting');
+          this.performAction({refer_status: this.referStatus})
+            .catch((err) => this.logger.error(err, 'TaskSipRefer:exec - error performing action'));
+          this.notifyTaskDone();
+        }, 15000);
         await this.awaitTaskDone();
+        if (this._notifyTimer) {
+          clearTimeout(this._notifyTimer);
+          this._notifyTimer = null;
+        }
       }
       else {
         await this.performAction({refer_status: this.referStatus});
@@ -71,10 +81,10 @@ class TaskSipRefer extends Task {
     const contentType = req.get('Content-Type');
     this.logger.debug({body: req.body}, `TaskSipRefer:_handleNotify got ${contentType}`);
 
-    if (contentType === 'message/sipfrag') {
+    if (contentType?.includes('message/sipfrag')) {
       const arr = /SIP\/2\.0\s+(\d+)/.exec(req.body);
       if (arr) {
-        const status = arr[1];
+        const status = typeof arr[1] === 'string' ? parseInt(arr[1], 10) : arr[1];
         this.logger.debug(`TaskSipRefer:_handleNotify: call got status ${status}`);
         if (this.eventHook) {
           const b3 = this.getTracingPropagation();

package.json

@@ -1,6 +1,6 @@
 {
   "name": "jambonz-feature-server",
-  "version": "v0.7.8",
+  "version": "v0.7.9",
   "main": "app.js",
   "engines": {
     "node": ">= 10.16.0"
@@ -26,7 +26,7 @@
   "dependencies": {
     "@jambonz/db-helpers": "^0.7.3",
     "@jambonz/http-health-check": "^0.0.1",
-    "@jambonz/realtimedb-helpers": "^0.5.9",
+    "@jambonz/realtimedb-helpers": "^0.6.3",
     "@jambonz/stats-collector": "^0.1.6",
     "@jambonz/time-series": "^0.2.5",
     "@opentelemetry/api": "^1.1.0",
@@ -43,7 +43,7 @@
     "debug": "^4.3.4",
     "deepcopy": "^2.1.0",
     "drachtio-fsmrf": "^3.0.16",
-    "drachtio-srf": "^4.5.20",
+    "drachtio-srf": "^4.5.21",
     "express": "^4.18.2",
     "ip": "^1.1.8",
     "moment": "^2.29.4",

test/index.js

@@ -8,5 +8,6 @@ require('./gather-tests');
 require('./sip-request-tests');
 require('./create-call-test');
 require('./play-tests');
+require('./sip-refer-tests');
 require('./remove-test-db');
 require('./docker_stop');

test/scenarios/uac-refer-no-notify.xml

@@ -0,0 +1,95 @@
+<?xml version="1.0" encoding="ISO-8859-1" ?>
+<!DOCTYPE scenario SYSTEM "sipp.dtd">
+
+<scenario name="Basic Sipstone UAC">
+  <!-- In client mode (sipp placing calls), the Call-ID MUST be         -->
+  <!-- generated by sipp. To do so, use [call_id] keyword.                -->
+  <send retrans="500">
+    <![CDATA[
+
+    INVITE sip:[to]@[remote_ip]:[remote_port] SIP/2.0
+    Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch]
+    From: [from] <sip:[from]@[local_ip]:[local_port]>;tag=[pid]SIPpTag00[call_number]
+    To: <sip:[to]@[remote_ip]:[remote_port]>
+    Call-ID: [call_id]
+    CSeq: 1 INVITE
+    Contact: sip:[from]@[local_ip]:[local_port]
+    Max-Forwards: 70
+    X-Account-Sid: bb845d4b-83a9-4cde-a6e9-50f3743bab3f
+    Subject: uac-refer-no-notify.xml
+    Content-Type: application/sdp
+    Content-Length: [len]
+
+    v=0
+    o=user1 53655765 2353687637 IN IP[local_ip_type] [local_ip]
+    s=-
+    c=IN IP[media_ip_type] [media_ip]
+    t=0 0
+    m=audio [media_port] RTP/AVP 0
+    a=rtpmap:0 PCMU/8000
+
+    ]]>
+  </send>
+
+  <recv response="100"
+        optional="true">
+  </recv>
+
+  <recv response="180" optional="true">
+  </recv>
+
+  <recv response="183" optional="true">
+  </recv>
+
+  <!-- By adding rrs="true" (Record Route Sets), the route sets         -->
+  <!-- are saved and used for following messages sent. Useful to test   -->
+  <!-- against stateful SIP proxies/B2BUAs.                             -->
+  <recv response="200" rtd="true">
+  </recv>
+
+  <!-- Packet lost can be simulated in any send/recv message by         -->
+  <!-- by adding the 'lost = "10"'. Value can be [1-100] percent.       -->
+  <send>
+    <![CDATA[
+
+      ACK sip:[service]@[remote_ip]:[remote_port] SIP/2.0
+      Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch]
+      From: sipp <sip:sipp@[local_ip]:[local_port]>;tag=[pid]SIPpTag00[call_number]
+      To: [service] <sip:[service]@[remote_ip]:[remote_port]>[peer_tag_param]
+      Call-ID: [call_id]
+      CSeq: 1 ACK
+      Max-Forwards: 70
+      Subject: REFER test with no NOT
+      Content-Length: 0
+
+    ]]>
+  </send>
+
+  <!-- receive re-invite -->
+  <recv request="REFER" crlf="true"/>
+
+  <send>
+    <![CDATA[
+
+      SIP/2.0 202 Accepted
+      [last_Via:]
+      [last_From:]
+      [last_To:]
+      [last_Call-ID:]
+      [last_CSeq:]
+      Contact: sip:sipp@[local_ip]:[local_port]
+      Content-Type: application/sdp
+      Content-Length: [len]
+
+      v=0
+      o=user1 53655765 2353687637 IN IP[local_ip_type] [local_ip]
+      s=-
+      c=IN IP[media_ip_type] [media_ip]
+      t=0 0
+      m=audio [media_port] RTP/AVP 0
+      a=rtpmap:0 PCMU/8000
+
+    ]]>
+  </send>
+
+</scenario>

test/scenarios/uac-refer-with-notify.xml

@@ -0,0 +1,115 @@
+<?xml version="1.0" encoding="ISO-8859-1" ?>
+<!DOCTYPE scenario SYSTEM "sipp.dtd">
+
+<scenario name="Basic Sipstone UAC">
+  <!-- In client mode (sipp placing calls), the Call-ID MUST be         -->
+  <!-- generated by sipp. To do so, use [call_id] keyword.                -->
+  <send retrans="500">
+    <![CDATA[
+
+    INVITE sip:[to]@[remote_ip]:[remote_port] SIP/2.0
+    Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch]
+    From: [from] <sip:[from]@[local_ip]:[local_port]>;tag=[pid]SIPpTag00[call_number]
+    To: <sip:16174000000@[remote_ip]:[remote_port]>
+    Call-ID: [call_id]
+    CSeq: 1 INVITE
+    Contact: sip:[from]@[local_ip]:[local_port]
+    Max-Forwards: 70
+    X-Account-Sid: bb845d4b-83a9-4cde-a6e9-50f3743bab3f
+    Subject: uac-refer-with-notify.xml
+    Content-Type: application/sdp
+    Content-Length: [len]
+
+    v=0
+    o=user1 53655765 2353687637 IN IP[local_ip_type] [local_ip]
+    s=-
+    c=IN IP[media_ip_type] [media_ip]
+    t=0 0
+    m=audio [media_port] RTP/AVP 0
+    a=rtpmap:0 PCMU/8000
+
+    ]]>
+  </send>
+
+  <recv response="100"
+        optional="true">
+  </recv>
+
+  <recv response="180" optional="true">
+  </recv>
+
+  <recv response="183" optional="true">
+  </recv>
+
+  <!-- By adding rrs="true" (Record Route Sets), the route sets         -->
+  <!-- are saved and used for following messages sent. Useful to test   -->
+  <!-- against stateful SIP proxies/B2BUAs.                             -->
+  <recv response="200" rtd="true">
+  </recv>
+
+  <!-- Packet lost can be simulated in any send/recv message by         -->
+  <!-- by adding the 'lost = "10"'. Value can be [1-100] percent.       -->
+  <send>
+    <![CDATA[
+
+      ACK sip:[service]@[remote_ip]:[remote_port] SIP/2.0
+      Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch]
+      From: sipp <sip:sipp@[local_ip]:[local_port]>;tag=[pid]SIPpTag00[call_number]
+      To: <sip:16174000000@[remote_ip]:[remote_port]>[peer_tag_param]
+      Call-ID: [call_id]
+      CSeq: 1 ACK
+      Max-Forwards: 70
+      Subject: uac-refer-with-notify.xml
+      Content-Length: 0
+
+    ]]>
+  </send>
+
+  <!-- receive re-invite -->
+  <recv request="REFER" crlf="true"/>
+
+  <send>
+    <![CDATA[
+
+      SIP/2.0 202 Accepted
+      [last_Via:]
+      [last_From:]
+      [last_To:]
+      [last_Call-ID:]
+      [last_CSeq:]
+      Contact: sip:sipp@[local_ip]:[local_port]
+      Content-Type: application/sdp
+      Content-Length: [len]
+
+      v=0
+      o=user1 53655765 2353687637 IN IP[local_ip_type] [local_ip]
+      s=-
+      c=IN IP[media_ip_type] [media_ip]
+      t=0 0
+      m=audio [media_port] RTP/AVP 0
+      a=rtpmap:0 PCMU/8000
+
+    ]]>
+  </send>
+
+  <send retrans="500">
+    <![CDATA[
+
+      NOTIFY sip:[service]@[remote_ip]:[remote_port] SIP/2.0
+      Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch]
+      From: sipp <sip:sipp@[local_ip]:[local_port]>;tag=[pid]SIPpTag00[call_number]
+      To: <sip:16174000000@[remote_ip]:[remote_port]>[peer_tag_param]
+      Call-ID: [call_id]
+      CSeq: 2 NOTIFY
+      Contact: sip:sipp@[local_ip]:[local_port]
+      Max-Forwards: 70
+      Subject: uac-refer-with-notify.xml
+      Content-Type: message/sipfrag;version=2.0
+      Content-Length: 16
+      
+      SIP/2.0 200 OK
+    ]]>
+  </send>
+  <recv response="200"</recv>
+      
+</scenario>

test/sip-refer-tests.js

@@ -0,0 +1,100 @@
+const test = require('tape');
+const { sippUac } = require('./sipp')('test_fs');
+const clearModule = require('clear-module');
+const {provisionCallHook, provisionCustomHook, provisionActionHook} = require('./utils')
+const bent = require('bent');
+const getJSON = bent('json')
+
+const sleepFor = async(ms) => new Promise(resolve => setTimeout(resolve, ms));
+
+process.on('unhandledRejection', (reason, p) => {
+  console.log('Unhandled Rejection at: Promise', p, 'reason:', reason);
+});
+
+function connect(connectable) {
+  return new Promise((resolve, reject) => {
+    connectable.on('connect', () => {
+      return resolve();
+    });
+  });
+}
+
+test('\'refer\' tests w/202 and NOTIFY', {timeout: 25000}, async(t) => {
+  clearModule.all();
+  const {srf, disconnect} = require('../app');
+
+  try {
+    await connect(srf);
+
+    // GIVEN
+    const verbs = [
+      {
+        verb: 'say',
+        text: 'silence_stream://100'
+      },
+      {
+        verb: 'sip:refer',
+        referTo: '123456',
+        actionHook: '/actionHook'
+      }
+    ];
+    const noVerbs = [];
+
+    const from = 'refer_with_notify';
+    provisionCallHook(from, verbs);
+    provisionActionHook(from, noVerbs)
+
+    // THEN
+    await sippUac('uac-refer-with-notify.xml', '172.38.0.10', from);
+    t.pass('refer: successfully received 202 Accepted');
+    await sleepFor(1000);
+    const obj  = await getJSON(`http:127.0.0.1:3100/lastRequest/${from}_actionHook`);
+    t.ok(obj.body.final_referred_call_status === 200, 'refer: successfully received NOTIFY with 200 OK');
+    //console.log(`obj: ${JSON.stringify(obj)}`);
+    disconnect();
+  } catch (err) {
+    console.log(`error received: ${err}`);
+    disconnect();
+    t.error(err);
+  }
+});
+
+test('\'refer\' tests w/202 but no NOTIFY', {timeout: 25000}, async(t) => {
+  clearModule.all();
+  const {srf, disconnect} = require('../app');
+
+  try {
+    await connect(srf);
+
+    // GIVEN
+    const verbs = [
+      {
+        verb: 'say',
+        text: 'silence_stream://100'
+      },
+      {
+        verb: 'sip:refer',
+        referTo: '123456',
+        actionHook: '/actionHook'
+      }
+    ];
+    const noVerbs = [];
+
+    const from = 'refer_no_notify';
+    provisionCallHook(from, verbs);
+    provisionActionHook(from, noVerbs)
+
+    // THEN
+    await sippUac('uac-refer-no-notify.xml', '172.38.0.10', from);
+    t.pass('refer: successfully received 202 Accepted w/o NOTIFY');
+    await sleepFor(17000);
+    const obj  = await getJSON(`http:127.0.0.1:3100/lastRequest/${from}_actionHook`);
+    console.log(`obj: ${JSON.stringify(obj)}`);
+    t.ok(obj.body.refer_status === 202, 'refer: successfully timed out and reported 202');
+    disconnect();
+  } catch (err) {
+    console.log(`error received: ${err}`);
+    disconnect();
+    t.error(err);
+  }
+});

test/sip-tests.js

@@ -53,6 +53,13 @@ test('incoming call tests', (t) => {
     .then(() => {
       return t.pass('handles in-dialog requests');
     })
+    .then(() => {
+      return sippUac('uac-refer-no-notify.xml', '172.38.0.30');
+    })
+    .then(() => {
+      return t.pass('handles sip:refer where we get 202 but no NOTIFY');
+    })
+
     .then(() => {
       srf.disconnect();
       t.end();

test/utils.js

@@ -24,4 +24,13 @@ const provisionCustomHook = (from, verbs) => {
   post(`/customHookMapping`, mapping);
 }
 
-module.exports = { provisionCallHook, provisionCustomHook}
+const provisionActionHook = (from, verbs) => {
+  const mapping = {
+    from,
+    data: JSON.stringify(verbs)
+  };
+  const post = bent('http://127.0.0.1:3100', 'POST', 'string', 200);
+  post(`/actionHook`, mapping);
+}
+
+module.exports = { provisionCallHook, provisionCustomHook, provisionActionHook}

tracer.js

@@ -22,7 +22,7 @@ module.exports = (serviceName) => {
     });
 
     let exporter;
-    if (process.env.OTEL_EXPORTER_JAEGER_AGENT_HOST) {
+    if (process.env.OTEL_EXPORTER_JAEGER_AGENT_HOST || process.env.OTEL_EXPORTER_JAEGER_ENDPOINT) {
       exporter = new JaegerExporter();
     }
     else if (process.env.OTEL_EXPORTER_ZIPKIN_URL) {