#251 - unhandled exception in Session#_notifyCallStatusChange

* when clearing stack on background gather (bargein), search to see if there is a config further down the stack that turns bargein off, and if so clear only down to there (#220)

* avoid clearing the stack twice when a background gather bargein occurs

* fix bug from prev commit

.github/workflows/build.yml

@@ -1,16 +1,15 @@
 name: CI
 
-on:
-  push:
+on: [push, pull_request]
 
 jobs:
   build:
-    runs-on: ubuntu-20.04
+    runs-on: ubuntu-latest
     steps:
-      - uses: actions/checkout@v2
-      - uses: actions/setup-node@v1
+      - uses: actions/checkout@v3
+      - uses: actions/setup-node@v3
         with:
-          node-version: 16
+          node-version: lts/*
       - run: npm ci
       - run: npm run jslint
       - run: docker pull drachtio/sipp
@@ -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 }}

.github/workflows/docker-publish.yml

@@ -20,7 +20,7 @@ jobs:
     if: github.event_name == 'push'
 
     steps:
-      - uses: actions/checkout@v2
+      - uses: actions/checkout@v3
 
       - name: Build image
         run: docker build . --file Dockerfile --tag $IMAGE_NAME

.gitignore

@@ -40,4 +40,5 @@ examples/*
 ecosystem.config.js
 .vscode
 test/credentials/*.json
-run-tests.sh
+run-tests.sh
+run-coverage.sh

Dockerfile

@@ -1,4 +1,4 @@
-FROM --platform=linux/amd64 node:18.9.0-alpine3.16 as base
+FROM --platform=linux/amd64 node:18.12.1-alpine3.16 as base
 
 RUN apk --update --no-cache add --virtual .builds-deps build-base python3
 

lib/http-routes/api/create-call.js

@@ -3,7 +3,7 @@ const makeTask = require('../../tasks/make_task');
 const RestCallSession = require('../../session/rest-call-session');
 const CallInfo = require('../../session/call-info');
 const {CallDirection, CallStatus} = require('../../utils/constants');
-const { v4: uuidv4 } = require('uuid');
+const uuidv4 = require('uuid-random');
 const SipError = require('drachtio-srf').SipError;
 const sysError = require('./error');
 const HttpRequestor = require('../../utils/http-requestor');
@@ -136,7 +136,7 @@ router.post('/', async(req, res) => {
     }
     else if (!app.notifier) {
       logger.debug('creating null call status hook');
-      app.notifier = {request: () => {}};
+      app.notifier = {request: () => {}, close: () => {}};
     }
 
     /* now launch the outdial */

lib/http-routes/api/messaging.js

@@ -34,6 +34,7 @@ router.post('/:partner', async(req, res) => {
     carrier: req.params.partner,
     messageSid: app.messageSid,
     accountSid: app.accountSid,
+    serviceProviderSid: account.service_provider_sid,
     applicationSid: app.applicationSid,
     from: req.body.from,
     to: req.body.to,

lib/http-routes/api/update-call.js

@@ -41,7 +41,7 @@ function retrieveCallSession(callSid, opts) {
 router.post('/:callSid', async(req, res) => {
   const logger = req.app.locals.logger;
   const callSid = req.params.callSid;
-  logger.debug({body: req.body}, 'got upateCall request');
+  logger.debug({body: req.body}, 'got updateCall request');
   try {
     const cs = retrieveCallSession(callSid, req.body);
     if (!cs) {

lib/middleware.js

@@ -1,4 +1,4 @@
-const { v4: uuidv4 } = require('uuid');
+const uuidv4 = require('uuid-random');
 const {CallDirection, AllowedSipRecVerbs} = require('./utils/constants');
 const {parseSiprecPayload} = require('./utils/siprec-utils');
 const CallInfo = require('./session/call-info');
@@ -118,6 +118,7 @@ module.exports = function(srf, logger) {
     const {span} = rootSpan.startChildSpan('lookupAccountDetails');
     try {
       req.locals.accountInfo = await lookupAccountDetails(account_sid);
+      req.locals.service_provider_sid = req.locals.accountInfo?.account?.service_provider_sid;
       span.end();
       if (!req.locals.accountInfo.account.is_active) {
         logger.info(`Account is inactive or suspended ${account_sid}`);
@@ -224,29 +225,32 @@ module.exports = function(srf, logger) {
       * create a requestor that we will use for all http requests we make during the call.
       * also create a notifier for call status events (if not needed, its a no-op).
       */
+
+      /* allow for caching data - when caching treat retrieved data as immutable */
+      const app2 = process.env.JAMBONES_MYSQL_REFRESH_TTL ? JSON.parse(JSON.stringify(app)) : app;
       if ('WS' === app.call_hook?.method ||
         app.call_hook?.url.startsWith('ws://') || app.call_hook?.url.startsWith('wss://')) {
-        app.requestor = new WsRequestor(logger, account_sid, app.call_hook, accountInfo.account.webhook_secret) ;
-        app.notifier = app.requestor;
-        app.call_hook.method = 'WS';
+        app2.requestor = new WsRequestor(logger, account_sid, app.call_hook, accountInfo.account.webhook_secret) ;
+        app2.notifier = app.requestor;
+        app2.call_hook.method = 'WS';
       }
       else {
-        app.requestor = new HttpRequestor(logger, account_sid, app.call_hook, accountInfo.account.webhook_secret);
-        if (app.call_status_hook) app.notifier = new HttpRequestor(logger, account_sid, app.call_status_hook,
+        app2.requestor = new HttpRequestor(logger, account_sid, app.call_hook, accountInfo.account.webhook_secret);
+        if (app.call_status_hook) app2.notifier = new HttpRequestor(logger, account_sid, app.call_status_hook,
           accountInfo.account.webhook_secret);
-        else app.notifier = {request: () => {}};
+        else app2.notifier = {request: () => {}};
       }
 
-      req.locals.application = app;
-      const obj = Object.assign({}, app);
-      delete obj.requestor;
-      delete obj.notifier;
+      req.locals.application = app2;
+
       // eslint-disable-next-line no-unused-vars
-      const {call_hook, call_status_hook, ...appInfo} = obj;  // mask sensitive data like user/pass on webhook
-      logger.info({app: appInfo}, `retrieved application for incoming call to ${req.locals.calledNumber}`);
+      const {call_hook, call_status_hook, ...appInfo} = app;  // mask sensitive data like user/pass on webhook
+      // eslint-disable-next-line no-unused-vars
+      const {requestor, notifier, ...loggable} = appInfo;
+      logger.info({app: loggable}, `retrieved application for incoming call to ${req.locals.calledNumber}`);
       req.locals.callInfo = new CallInfo({
         req,
-        app,
+        app: app2,
         direction: CallDirection.Inbound,
         traceId: rootSpan.traceId
       });
@@ -273,7 +277,9 @@ module.exports = function(srf, logger) {
       }
       /* retrieve the application to execute for this inbound call */
       const params = Object.assign(['POST', 'WS'].includes(app.call_hook.method) ? {sip: req.msg} : {},
-        req.locals.callInfo, {
+        req.locals.callInfo,
+        {service_provider_sid: req.locals.service_provider_sid},
+        {
           defaults: {
             synthesizer: {
               vendor: app.speech_synthesis_vendor,

lib/session/call-info.js

@@ -1,6 +1,6 @@
 const {CallDirection, CallStatus} = require('../utils/constants');
 const parseUri = require('drachtio-srf').parseUri;
-const { v4: uuidv4 } = require('uuid');
+const uuidv4 = require('uuid-random');
 /**
  * @classdesc Represents the common information for all calls
  * that is provided in call status webhooks

lib/session/call-session.js

@@ -83,6 +83,10 @@ class CallSession extends Emitter {
 
     this.requestor.on('command', this._onCommand.bind(this));
     this.requestor.on('connection-dropped', this._onWsConnectionDropped.bind(this));
+    this.requestor.on('handover', (newRequestor) => {
+      this.logger.info(`handover to new base url ${newRequestor.url}`);
+      this.application.requestor = newRequestor;
+    });
   }
 
   /**
@@ -445,14 +449,18 @@ 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;
       this.backgroundGatherTask
-        .once('dtmf', this._clearTasks.bind(this))
-        .once('vad', this._clearTasks.bind(this))
-        .once('transcription', this._clearTasks.bind(this))
-        .once('timeout', this._clearTasks.bind(this));
+        .once('dtmf', this._clearTasks.bind(this, this.backgroundGatherTask))
+        .once('vad', this._clearTasks.bind(this, this.backgroundGatherTask))
+        .once('transcription', this._clearTasks.bind(this, this.backgroundGatherTask))
+        .once('timeout', this._clearTasks.bind(this, this.backgroundGatherTask));
       this.logger.info({gather}, 'CallSession:enableBotMode - starting background gather');
       const resources = await this._evaluatePreconditions(this.backgroundGatherTask);
       const {span, ctx} = this.rootSpan.startChildSpan(`background-gather:${this.backgroundGatherTask.summary}`);
@@ -551,7 +559,9 @@ class CallSession extends Emitter {
             api_key: credential.api_key,
             region: credential.region,
             use_custom_stt: credential.use_custom_stt,
-            custom_stt_endpoint: credential.custom_stt_endpoint
+            custom_stt_endpoint: credential.custom_stt_endpoint,
+            use_custom_tts: credential.use_custom_tts,
+            custom_tts_endpoint: credential.custom_tts_endpoint
           };
         }
         else if ('wellsaid' === vendor) {
@@ -586,13 +596,19 @@ class CallSession extends Emitter {
       this.logger.info(`CallSession:exec starting task #${stackNum}:${taskNum}: ${task.name}`);
       try {
         const resources = await this._evaluatePreconditions(task);
+        let skip = false;
         this.currentTask = task;
         if (TaskName.Gather === task.name && this.isBotModeEnabled) {
-          const timeout = task.timeout;
-          this.logger.info(`CallSession:exec skipping #${stackNum}:${taskNum}: ${task.name}`);
-          this.backgroundGatherTask.updateTimeout(timeout);
+          if (this.backgroundGatherTask.updateTaskInProgress(task)) {
+            this.logger.info(`CallSession:exec skipping #${stackNum}:${taskNum}: ${task.name}`);
+            skip = true;
+          }
+          else {
+            this.logger.info('CallSession:exec disabling bot mode to start gather with new options');
+            this.disableBotMode();
+          }
         }
-        else {
+        if (!skip) {
           const {span, ctx} = this.rootSpan.startChildSpan(`verb:${task.summary}`);
           task.span = span;
           task.ctx = ctx;
@@ -983,14 +999,32 @@ class CallSession extends Emitter {
     }
   }
 
-  kill() {
+  kill(onBackgroundGatherBargein = false) {
     if (this.isConfirmCallSession) this.logger.debug('CallSession:kill (ConfirmSession)');
     else this.logger.info('CallSession:kill');
     if (this.currentTask) {
       this.currentTask.kill(this);
       this.currentTask = null;
     }
-    this.tasks = [];
+    if (onBackgroundGatherBargein) {
+      /* search for a config with bargein disabled */
+      while (this.tasks.length) {
+        const t = this.tasks[0];
+        if (t.name === TaskName.Config && t.bargeIn?.enable === false) {
+          /* found it, clear to that point and remove the disable
+            because we likely already received a partial transcription
+            and we don't want to kill the background gather before we
+            get the full transcription.
+          */
+          delete t.bargeIn.enable;
+          this._bargeInEnabled = false;
+          this.logger.info('CallSession:kill - found bargein disabled in the stack, clearing to that point');
+          break;
+        }
+        this.tasks.shift();
+      }
+    }
+    else this.tasks = [];
     this.taskIdx = 0;
   }
 
@@ -1274,6 +1308,7 @@ class CallSession extends Emitter {
     }
     this.tmpFiles.clear();
     this.requestor && this.requestor.close();
+    this.notifier && this.notifier.close();
 
     this.rootSpan && this.rootSpan.end();
   }
@@ -1556,7 +1591,7 @@ class CallSession extends Emitter {
    * @param {number} sipStatus - current sip status
    * @param {number} [duration] - duration of a completed call, in seconds
    */
-  _notifyCallStatusChange({callStatus, sipStatus, sipReason, duration}) {
+  async _notifyCallStatusChange({callStatus, sipStatus, sipReason, duration}) {
     if (this.callMoved) return;
 
     /* race condition: we hang up at the same time as the caller */
@@ -1576,7 +1611,7 @@ class CallSession extends Emitter {
     try {
       const b3 = this.b3;
       const httpHeaders = b3 && {b3};
-      this.notifier.request('call:status', this.call_status_hook, this.callInfo.toJSON(), httpHeaders);
+      await this.notifier.request('call:status', this.call_status_hook, this.callInfo.toJSON(), httpHeaders);
       span.end();
     } catch (err) {
       span.end();
@@ -1597,11 +1632,12 @@ class CallSession extends Emitter {
     });
   }
 
-  _clearTasks(evt) {
-    if (this.requestor instanceof WsRequestor) {
+  _clearTasks(backgroundGather, evt) {
+    if (this.requestor instanceof WsRequestor && !backgroundGather.cleared) {
       this.logger.info({evt}, 'CallSession:_clearTasks on event from background gather');
       try {
-        this.kill();
+        backgroundGather.cleared = true;
+        this.kill(true);
       } catch (err) {}
     }
   }

lib/tasks/config.js

@@ -146,7 +146,11 @@ class TaskConfig extends Task {
   _onAmdEvent(cs, evt) {
     this.logger.info({evt}, 'Config:_onAmdEvent');
     const {actionHook} = this.data.amd;
-    this.performHook(cs, actionHook, evt);
+    this.performHook(cs, actionHook, evt)
+      .catch((err) => {
+        this.logger.error({err}, 'Config:_onAmdEvent - error calling actionHook');
+      });
+
   }
 }
 

lib/tasks/dial.js

@@ -689,7 +689,10 @@ class TaskDial extends Task {
   _onAmdEvent(cs, evt) {
     this.logger.info({evt}, 'Dial:_onAmdEvent');
     const {actionHook} = this.data.amd;
-    this.performHook(cs, actionHook, evt);
+    this.performHook(cs, actionHook, evt)
+      .catch((err) => {
+        this.logger.error({err}, 'Dial:_onAmdEvent - error calling actionHook');
+      });
   }
 }
 

lib/tasks/gather.js

@@ -83,6 +83,7 @@ class TaskGather extends Task {
       this.initialSpeechTimeoutMs = recognizer.initialSpeechTimeoutMs || 0;
       this.azureServiceEndpoint = recognizer.azureServiceEndpoint;
       this.azureSttEndpointId = recognizer.azureSttEndpointId;
+      this.azureAudioLogging = recognizer.audioLogging;
     }
     else {
       this.hints = [];
@@ -159,6 +160,14 @@ class TaskGather extends Task {
         asrDtmfTerminationDigit: this.asrDtmfTerminationDigit
       }, 'Gather:exec - enabling continuous ASR since it is turned on for the session');
     }
+    if (process.env.JAMBONZ_GATHER_EARLY_HINTS_MATCH &&
+      !this.isContinuousAsr &&
+      this.hints.length > 0 && this.hints.length <= 10) {
+      this.earlyHintsMatch = true;
+      this.interim = true;
+      this.logger.debug('Gather:exec - early hints match enabled');
+    }
+
     this.ep = ep;
     if ('default' === this.vendor || !this.vendor) this.vendor = cs.speechRecognizerVendor;
     if ('default' === this.language || !this.language) this.language = cs.speechRecognizerLanguage;
@@ -177,10 +186,15 @@ class TaskGather extends Task {
 
     const startListening = (cs, ep) => {
       this._startTimer();
-      if (this.isContinuousAsr && 0 === this.timeout) this._startAsrTimer();
+      // dont start asr timer until we have a transcription
+      //if (this.isContinuousAsr && 0 === this.timeout) this._startAsrTimer();
       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);
           })
@@ -213,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);
@@ -250,10 +270,15 @@ class TaskGather extends Task {
     this._resolve('killed');
   }
 
-  updateTimeout(timeout) {
-    this.logger.info(`TaskGather:updateTimeout - updating timeout to ${timeout}`);
+  updateTaskInProgress(opts) {
+    if (!this.needsStt && opts.input.includes('speech')) {
+      this.logger.info('TaskGather:updateTaskInProgress - adding speech to a background gather');
+      return false; // this needs be handled by killing the background gather and starting a new one
+    }
+    const {timeout} = opts;
     this.timeout = timeout;
     this._startTimer();
+    return true;
   }
 
   _onDtmf(cs, ep, evt) {
@@ -381,6 +406,7 @@ class TaskGather extends Task {
       else {
         opts.AZURE_SPEECH_ALTERNATIVE_LANGUAGE_CODES = '';
       }
+      if (this.azureAudioLogging) opts.AZURE_AUDIO_LOGGING = 1;
       if (this.requestSnr) opts.AZURE_REQUEST_SNR = 1;
       if (this.profanityOption && this.profanityOption !== 'raw') opts.AZURE_PROFANITY_OPTION = this.profanityOption;
       if (this.azureServiceEndpoint) opts.AZURE_SERVICE_ENDPOINT = this.azureServiceEndpoint;
@@ -424,8 +450,7 @@ class TaskGather extends Task {
     if (0 === this.timeout) return;
     this._clearTimer();
     this._timeoutTimer = setTimeout(() => {
-      if (this.isContinuousAsr) this._startAsrTimer();
-      else this._resolve(this.digitBuffer.length >= this.minDigits ? 'dtmf-num-digits' : 'timeout');
+      this._resolve(this.digitBuffer.length >= this.minDigits ? 'dtmf-num-digits' : 'timeout');
     }, this.timeout);
   }
 
@@ -524,6 +549,15 @@ class TaskGather extends Task {
       }
     }
 
+    if (this.earlyHintsMatch && evt.is_final === false) {
+      const transcript = evt.alternatives[0].transcript?.toLowerCase();
+      if (this.hints.find((h) => h.toLowerCase() === transcript)) {
+        this.logger.debug({evt}, 'Gather:_onTranscription: early hint match');
+        this._resolve('speech', evt);
+        return;
+      }
+    }
+
     /* count words for bargein feature */
     const words = evt.alternatives[0].transcript.split(' ').length;
     const bufferedWords = this._bufferedTranscripts.reduce((count, e) => {

lib/tasks/hangup.js

@@ -18,6 +18,7 @@ class TaskHangup extends Task {
     await super.exec(cs);
     try {
       await dlg.destroy({headers: this.headers});
+      cs._callReleased();
     } catch (err) {
       this.logger.error(err, 'TaskHangup:exec - Error hanging up call');
     }

lib/tasks/message.js

@@ -1,7 +1,7 @@
 const Task = require('./task');
 const {TaskName, TaskPreconditions} = require('../utils/constants');
 const bent = require('bent');
-const { v4: uuidv4 } = require('uuid');
+const uuidv4 = require('uuid-random');
 
 class TaskMessage extends Task {
   constructor(logger, opts) {

lib/tasks/say.js

@@ -164,6 +164,10 @@ class TaskSay extends Task {
           'tts.voice': voice
         });
         try {
+          if (vendor === 'microsoft' && this.synthesizer.azureServiceEndpoint) {
+            credentials.use_custom_tts = true;
+            credentials.custom_tts_endpoint = this.synthesizer.azureServiceEndpoint;
+          }
           const {filePath, servedFromCache} = await synthAudio(stats, {
             text,
             vendor,

lib/tasks/sip_refer.js

@@ -36,6 +36,7 @@ class TaskSipRefer extends Task {
         method: 'REFER',
         headers: {
           ...this.headers,
+          ...(this.referToIsUri && {'X-Refer-To-Leave-Untouched': true}),
           'Refer-To': referTo,
           'Referred-By': referredBy
         }
@@ -46,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});
@@ -70,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();
@@ -100,6 +111,7 @@ class TaskSipRefer extends Task {
       /* they may have only provided a phone number/user */
       referTo = `sip:${referTo}@${host}`;
     }
+    else this.referToIsUri = true;
     if (!referredBy) {
       /* default */
       referredBy = cs.req?.callingNumber || dlg.local.uri;

lib/tasks/specs.json

@@ -435,7 +435,8 @@
       "gender": {
         "type": "string",
         "enum": ["MALE", "FEMALE", "NEUTRAL"]
-      }
+      },
+      "azureServiceEndpoint": "string"
     },
     "required": [
       "vendor"
@@ -509,7 +510,8 @@
       "azureServiceEndpoint": "string",
       "azureSttEndpointId": "string",
       "asrDtmfTerminationDigit": "string",
-      "asrTimeout": "number"
+      "asrTimeout": "number",
+      "audioLogging": "boolean"
     },
     "required": [
       "vendor"

lib/tasks/task.js

@@ -1,5 +1,5 @@
 const Emitter = require('events');
-const { v4: uuidv4 } = require('uuid');
+const uuidv4 = require('uuid-random');
 const debug = require('debug')('jambonz:feature-server');
 const assert = require('assert');
 const {TaskPreconditions} = require('../utils/constants');

lib/tasks/transcribe.js

@@ -55,6 +55,7 @@ class TaskTranscribe extends Task {
     this.initialSpeechTimeoutMs = recognizer.initialSpeechTimeoutMs || 0;
     this.azureServiceEndpoint = recognizer.azureServiceEndpoint;
     this.azureSttEndpointId = recognizer.azureSttEndpointId;
+    this.azureAudioLogging = recognizer.audioLogging;
   }
 
   get name() { return TaskName.Transcribe; }
@@ -249,6 +250,7 @@ class TaskTranscribe extends Task {
       }
       if (this.altLanguages.length > 0) opts.AZURE_SPEECH_ALTERNATIVE_LANGUAGE_CODES = this.altLanguages.join(',');
       else opts.AZURE_SPEECH_ALTERNATIVE_LANGUAGE_CODES = '';
+      if (this.azureAudioLogging) opts.AZURE_AUDIO_LOGGING = 1;
       if (this.requestSnr) opts.AZURE_REQUEST_SNR = 1;
       if (this.profanityOption !== 'raw') opts.AZURE_PROFANITY_OPTION = this.profanityOption;
       if (this.initialSpeechTimeoutMs > 0) opts.AZURE_INITIAL_SPEECH_TIMEOUT_MS = this.initialSpeechTimeoutMs;

lib/utils/amd-utils.js

@@ -273,26 +273,46 @@ module.exports = (logger) => {
     amd
       .on(AmdEvents.NoSpeechDetected, (evt) => {
         task.emit('amd', {type: AmdEvents.NoSpeechDetected, ...evt});
-        ep.stopTranscription({vendor, bugname});
+        try {
+          ep.connected && ep.stopTranscription({vendor, bugname});
+        } catch (err) {
+          logger.info({err}, 'Error stopping transcription');
+        }
       })
       .on(AmdEvents.HumanDetected, (evt) => {
         task.emit('amd', {type: AmdEvents.HumanDetected, ...evt});
-        ep.stopTranscription({vendor, bugname});
+        try {
+          ep.connected && ep.stopTranscription({vendor, bugname});
+        } catch (err) {
+          logger.info({err}, 'Error stopping transcription');
+        }
       })
       .on(AmdEvents.MachineDetected, (evt) => {
         task.emit('amd', {type: AmdEvents.MachineDetected, ...evt});
       })
       .on(AmdEvents.DecisionTimeout, (evt) => {
         task.emit('amd', {type: AmdEvents.DecisionTimeout, ...evt});
-        ep.stopTranscription({vendor, bugname});
+        try {
+          ep.connected && ep.stopTranscription({vendor, bugname});
+        } catch (err) {
+          logger.info({err}, 'Error stopping transcription');
+        }
       })
       .on(AmdEvents.ToneTimeout, (evt) => {
         //task.emit('amd', {type: AmdEvents.ToneTimeout, ...evt});
-        ep.execute('avmd_stop').catch((err) => logger.info(err, 'Error stopping avmd'));
+        try {
+          ep.connected && ep.execute('avmd_stop').catch((err) => logger.info(err, 'Error stopping avmd'));
+        } catch (err) {
+          logger.info({err}, 'Error stopping avmd');
+        }
       })
       .on(AmdEvents.MachineStoppedSpeaking, () => {
         task.emit('amd', {type: AmdEvents.MachineStoppedSpeaking});
-        ep.stopTranscription({vendor, bugname});
+        try {
+          ep.connected && ep.stopTranscription({vendor, bugname});
+        } catch (err) {
+          logger.info({err}, 'Error stopping transcription');
+        }
       });
 
     /* start transcribing, and also listening for beep */

lib/utils/aws-sns-lifecycle.js

@@ -36,7 +36,7 @@ class SnsNotifier extends Emitter {
 
       logger.info(`SNS lifecycle server failed to bind port on ${e.port}, will try next port`);
       const server = this._doListen(logger, app, ++e.port, resolve);
-      server.on('error', this._handleErrors.bind(null, logger, app, resolve, reject));
+      server.on('error', this._handleErrors.bind(this, logger, app, resolve, reject));
       return;
     }
     reject(e);
@@ -120,7 +120,7 @@ class SnsNotifier extends Emitter {
       });
       return new Promise((resolve, reject) => {
         const server = this._doListen(this.logger, app, PORT, resolve);
-        server.on('error', this._handleErrors.bind(null, this.logger, app, resolve, reject));
+        server.on('error', this._handleErrors.bind(this, this.logger, app, resolve, reject));
       });
 
     } catch (err) {

lib/utils/db-utils.js

@@ -39,6 +39,8 @@ const speechMapper = (cred) => {
       obj.region = o.region;
       obj.use_custom_stt = o.use_custom_stt;
       obj.custom_stt_endpoint = o.custom_stt_endpoint;
+      obj.use_custom_tts = o.use_custom_tts;
+      obj.custom_tts_endpoint = o.custom_tts_endpoint;
     }
     else if ('wellsaid' === obj.vendor) {
       const o = JSON.parse(decrypt(credential));

lib/utils/http-listener.js

@@ -21,6 +21,7 @@ const handleErrors = (logger, app, resolve, reject, e) => {
     server.on('error', handleErrors.bind(null, logger, app, resolve, reject));
     return;
   }
+  logger.info({err: e, port: PORT}, 'httpListener error');
   reject(e);
 };
 
@@ -30,7 +31,7 @@ const createHttpListener = (logger, srf) => {
   app.use(express.urlencoded({ extended: true }));
   app.use(express.json());
   app.use('/', httpRoutes);
-  app.use((err, req, res, next) => {
+  app.use((err, _req, res, _next) => {
     logger.error(err, 'burped error');
     res.status(err.status || 500).json({msg: err.message});
   });

lib/utils/http-requestor.js

@@ -31,6 +31,8 @@ class HttpRequestor extends BaseRequestor {
     if (u.port) this._baseUrl = `${u.protocol}://${u.resource}:${u.port}`;
     else this._baseUrl = `${u.protocol}://${u.resource}`;
     this._protocol = u.protocol;
+    this._resource = u.resource;
+    this._port = u.port;
     this._search = u.search;
     this._usePools = process.env.HTTP_POOL && parseInt(process.env.HTTP_POOL);
 
@@ -98,7 +100,7 @@ class HttpRequestor extends BaseRequestor {
       }
       else {
         const u = parseUrl(url);
-        if (u.resource === this._resource && u.protocol === this._protocol) {
+        if (u.resource === this._resource && u.port === this._port && u.protocol === this._protocol) {
           client = this.client;
           path = u.pathname;
           query = u.query;

lib/utils/place-outdial.js

@@ -12,7 +12,7 @@ const deepcopy = require('deepcopy');
 const moment = require('moment');
 const stripCodecs = require('./strip-ancillary-codecs');
 const RootSpan = require('./call-tracer');
-const { v4: uuidv4 } = require('uuid');
+const uuidv4 = require('uuid-random');
 
 class SingleDialer extends Emitter {
   constructor({logger, sbcAddress, target, opts, application, callInfo, accountInfo, rootSpan, startSpan}) {
@@ -412,7 +412,7 @@ class SingleDialer extends Emitter {
       this.callInfo.updateCallStatus(callStatus, sipStatus, sipReason);
       if (typeof duration === 'number') this.callInfo.duration = duration;
       try {
-        this.requestor.request('call:status', this.application.call_status_hook, this.callInfo.toJSON());
+        this.notifier.request('call:status', this.application.call_status_hook, this.callInfo.toJSON());
       } catch (err) {
         this.logger.info(err, `SingleDialer:_notifyCallStatusChange error sending ${callStatus} ${sipStatus}`);
       }

lib/utils/sbc-pinger.js

@@ -1,5 +1,5 @@
 const assert = require('assert');
-const { v4: uuidv4 } = require('uuid');
+const uuidv4 = require('uuid-random');
 const {LifeCycleEvents, FS_UUID_SET_NAME} = require('./constants');
 const Emitter = require('events');
 const debug = require('debug')('jambonz:feature-server');

lib/utils/siprec-utils.js

@@ -1,5 +1,5 @@
 const xmlParser = require('xml2js').parseString;
-const { v4: uuidv4 } = require('uuid');
+const uuidv4 = require('uuid-random');
 const parseUri = require('drachtio-srf').parseUri;
 const transform = require('sdp-transform');
 const debug = require('debug')('jambonz:feature-server');

lib/utils/ws-requestor.js

@@ -54,7 +54,11 @@ class WsRequestor extends BaseRequestor {
     /* if we have an absolute url, and it is http then do a standard webhook */
     if (this._isAbsoluteUrl(url) && url.startsWith('http')) {
       this.logger.debug({hook}, 'WsRequestor: sending a webhook (HTTP)');
-      const requestor = new HttpRequestor(this.logger, this.account_sid, hook, this.secret);
+      const requestor = new HttpRequestor(this.logger, this.account_sid, {url: hook}, this.secret);
+      if (type === 'session:redirect') {
+        this.close();
+        this.emit('handover', requestor);
+      }
       return requestor.request(type, hook, params, httpHeaders);
     }
 
@@ -69,7 +73,7 @@ class WsRequestor extends BaseRequestor {
       this.connectInProgress = true;
       this.logger.debug(`WsRequestor:request(${this.id}) - connecting since we do not have a connection`);
       if (this.connections >= MAX_RECONNECTS) {
-        throw new Error(`max attempts connecting to ${this.url}`);
+        return Promise.reject(`max attempts connecting to ${this.url}`);
       }
       try {
         const startAt = process.hrtime();
@@ -79,7 +83,7 @@ class WsRequestor extends BaseRequestor {
       } catch (err) {
         this.logger.info({url, err}, 'WsRequestor:request - failed connecting');
         this.connectInProgress = false;
-        throw err;
+        return Promise.reject(err);
       }
     }
     assert(this.ws);
@@ -161,8 +165,9 @@ class WsRequestor extends BaseRequestor {
     this.logger.debug('WsRequestor:close closing socket');
     try {
       if (this.ws) {
-        this.ws.close();
+        this.ws.close(1000);
         this.ws.removeAllListeners();
+        this.ws = null;
       }
 
       for (const [msgid, obj] of this.messagesInFlight) {

package.json

@@ -1,6 +1,6 @@
 {
   "name": "jambonz-feature-server",
-  "version": "v0.7.7",
+  "version": "v0.7.13",
   "main": "app.js",
   "engines": {
     "node": ">= 10.16.0"
@@ -24,9 +24,9 @@
     "jslint": "eslint app.js lib"
   },
   "dependencies": {
+    "@jambonz/db-helpers": "^0.7.4",
     "@jambonz/http-health-check": "^0.0.1",
-    "@jambonz/db-helpers": "^0.6.19",
-    "@jambonz/realtimedb-helpers": "^0.4.35",
+    "@jambonz/realtimedb-helpers": "^0.6.3",
     "@jambonz/stats-collector": "^0.1.6",
     "@jambonz/time-series": "^0.2.5",
     "@opentelemetry/api": "^1.1.0",
@@ -42,10 +42,9 @@
     "bent": "^7.3.12",
     "debug": "^4.3.4",
     "deepcopy": "^2.1.0",
-    "drachtio-fsmrf": "^3.0.3",
-    "drachtio-srf": "^4.5.1",
-    "express": "^4.18.1",
-    "helmet": "^5.1.0",
+    "drachtio-fsmrf": "^3.0.16",
+    "drachtio-srf": "^4.5.21",
+    "express": "^4.18.2",
     "ip": "^1.1.8",
     "moment": "^2.29.4",
     "parse-url": "^8.1.0",
@@ -53,8 +52,8 @@
     "sdp-transform": "^2.14.1",
     "short-uuid": "^4.2.0",
     "to-snake-case": "^1.0.0",
-    "undici": "^5.8.2",
-    "uuid": "^8.3.2",
+    "undici": "^5.11.0",
+    "uuid-random": "^1.3.2",
     "verify-aws-sns-signature": "^0.1.0",
     "ws": "^8.8.0",
     "xml2js": "^0.4.23"

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) {