bugfix: db caching had side affects of using closed http requestors

Co-authored-by: Guilherme Rauen <g.rauen@cognigy.com>

.github/workflows/build.yml

@@ -5,12 +5,12 @@ on:
 
 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

.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

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/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

@@ -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,30 @@ 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
+      const {call_hook, call_status_hook, ...appInfo} = app;  // mask sensitive data like user/pass on webhook
       logger.info({app: appInfo}, `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 +275,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-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;
+    });
   }
 
   /**
@@ -551,7 +555,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 +592,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;
@@ -1274,6 +1286,7 @@ class CallSession extends Emitter {
     }
     this.tmpFiles.clear();
     this.requestor && this.requestor.close();
+    this.notifier && this.notifier.close();
 
     this.rootSpan && this.rootSpan.end();
   }

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 = [];
@@ -142,6 +143,14 @@ class TaskGather extends Task {
       this.logger.debug({hints: this.hints, hintsBoost: this.hintsBoost},
         'Gather:exec - applying global sttHints');
     }
+    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');
+    }
+
     if (cs.hasAltLanguages) {
       this.altLanguages = this.altLanguages.concat(cs.altLanguages);
       this.logger.debug({altLanguages: this.altLanguages},
@@ -177,7 +186,8 @@ 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(() => {
@@ -250,10 +260,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 +396,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 +440,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 +539,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/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
         }
@@ -100,6 +101,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/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

@@ -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/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);

package.json

@@ -25,8 +25,8 @@
   },
   "dependencies": {
     "@jambonz/http-health-check": "^0.0.1",
-    "@jambonz/db-helpers": "^0.6.19",
-    "@jambonz/realtimedb-helpers": "^0.4.35",
+    "@jambonz/db-helpers": "^0.7.3",
+    "@jambonz/realtimedb-helpers": "^0.5.9",
     "@jambonz/stats-collector": "^0.1.6",
     "@jambonz/time-series": "^0.2.5",
     "@opentelemetry/api": "^1.1.0",
@@ -42,8 +42,8 @@
     "bent": "^7.3.12",
     "debug": "^4.3.4",
     "deepcopy": "^2.1.0",
-    "drachtio-fsmrf": "^3.0.3",
-    "drachtio-srf": "^4.5.1",
+    "drachtio-fsmrf": "^3.0.8",
+    "drachtio-srf": "^4.5.18",
     "express": "^4.18.1",
     "helmet": "^5.1.0",
     "ip": "^1.1.8",