Feature/gather enhancements (#73)

* add bargein support to gather

* bugfix: gather handles interim results from azure

* gather: support for min/max digits and interdigit timeout

* add task summary to some log messages

* logging improvements

lib/session/call-session.js

@@ -636,7 +636,7 @@ class CallSession extends Emitter {
   }
 
   _onCommand({msgid, command, queueCommand, data}) {
-    this.logger.info({msgid, command, queueCommand, data}, 'CallSession:_onCommand - received command');
+    this.logger.info({msgid, command, queueCommand}, 'CallSession:_onCommand - received command');
     switch (command) {
       case 'redirect':
         if (Array.isArray(data)) {
@@ -646,9 +646,9 @@ class CallSession extends Emitter {
             this.replaceApplication(t);
           }
           else {
-            this.logger.info({t, tasks: this.tasks}, 'CallSession:_onCommand - about to queue tasks');
+            this.logger.info({tasks: listTaskNames(t)}, 'CallSession:_onCommand - queueing tasks');
             this.tasks.push(...t);
-            this.logger.debug({tasks: this.tasks}, 'CallSession:_onCommand - tasks have been queued');
+            this.logger.debug({tasks: listTaskNames(this.tasks)}, 'CallSession:_onCommand - updated task list');
           }
         }
         else this._lccCallHook(data);

lib/tasks/dial.js

@@ -135,6 +135,11 @@ class TaskDial extends Task {
     return !process.env.ANCHOR_MEDIA_ALWAYS && !this.listenTask && !this.transcribeTask;
   }
 
+  get summary() {
+    if (this.target.length === 1) return `${this.name}{type=${this.target[0].type}}`;
+    else return `${this.name}{${this.target.length} targets}`;
+  }
+
   async exec(cs) {
     await super.exec(cs);
     try {

lib/tasks/gather.js

@@ -9,6 +9,7 @@ const {
 
 const makeTask = require('./make_task');
 const assert = require('assert');
+const GATHER_STABILITY_THRESHOLD =  Number(process.env.JAMBONZ_GATHER_STABILITY_THRESHOLD || 0.7);
 
 class TaskGather extends Task {
   constructor(logger, opts, parentTask) {
@@ -16,12 +17,15 @@ class TaskGather extends Task {
     this.preconditions = TaskPreconditions.Endpoint;
 
     [
-      'finishOnKey', 'hints', 'input', 'numDigits',
+      'finishOnKey', 'hints', 'input', 'numDigits', 'minDigits', 'maxDigits',
-      'partialResultHook',
+      'interDigitTimeout', 'partialResultHook', 'bargein', 'dtmfBargein',
       'speechTimeout', 'timeout', 'say', 'play'
     ].forEach((k) => this[k] = this.data[k]);
 
-    this.timeout = (this.timeout || 5) * 1000;
+    /* when collecting dtmf, bargein on dtmf is true unless explicitly set to false */
+    if (this.dtmfBargein !== false && this.input.includes('digits')) this.dtmfBargein = true;
+
+    this.timeout = (this.timeout || 15) * 1000;
     this.interim = this.partialResultCallback;
     if (this.data.recognizer) {
       const recognizer = this.data.recognizer;
@@ -34,6 +38,9 @@ class TaskGather extends Task {
       const {enable, voiceMs = 0, mode = -1} = recognizer.vad || {};
       this.vad = {enable, voiceMs, mode};
 
+      this.listenDuringPrompt = this.data.listenDuringPrompt === false ? false : true;
+      this.minBargeinWordCount = this.data.minBargeinWordCount || 1;
+
       /* aws options */
       this.vocabularyName = recognizer.vocabularyName;
       this.vocabularyFilterName = recognizer.vocabularyFilterName;
@@ -64,6 +71,21 @@ class TaskGather extends Task {
       (this.playTask && this.playTask.earlyMedia);
   }
 
+  get summary() {
+    let s = `${this.name}{`;
+    if (this.input.length === 2) s += 'inputs=[speech,digits],';
+    else if (this.input.includes('digits')) s += 'inputs=digits';
+    else s += 'inputs=speech,';
+
+    if (this.input.includes('speech')) {
+      s += `vendor=${this.vendor},language=${this.language}`;
+    }
+    if (this.sayTask) s += ',with nested say task';
+    if (this.playTask) s += ',with nested play task';
+    s += '}';
+    return s;
+  }
+
   async exec(cs, ep) {
     await super.exec(cs);
     const {updateSpeechCredentialLastUsed} = require('../utils/db-utils')(this.logger, cs.srf);
@@ -84,29 +106,43 @@ class TaskGather extends Task {
       throw new Error(`no speech-to-text service credentials for ${this.vendor} have been configured`);
     }
 
+    const startListening = (cs, ep) => {
+      this._startTimer();
+      if (this.input.includes('speech') && !this.listenDuringPrompt) {
+        this._initSpeech(cs, ep)
+          .then(() => {
+            this._startTranscribing(ep);
+            return updateSpeechCredentialLastUsed(this.sttCredentials.speech_credential_sid);
+          })
+          .catch(() => {});
+      }
+    };
+
     try {
       if (this.sayTask) {
         this.sayTask.exec(cs, ep);  // kicked off, _not_ waiting for it to complete
         this.sayTask.on('playDone', (err) => {
-          if (!this.killed) this._startTimer();
+          if (err) return this.logger.error({err}, 'Gather:exec Error playing tts');
+          this.logger.debug('Gather: say task completed');
         });
       }
       else if (this.playTask) {
         this.playTask.exec(cs, ep);  // kicked off, _not_ waiting for it to complete
         this.playTask.on('playDone', (err) => {
-          if (!this.killed) this._startTimer();
+          if (err) return this.logger.error({err}, 'Gather:exec Error playing url');
+          if (!this.killed) startListening(cs, ep);
         });
       }
       else this._startTimer();
 
-      if (this.input.includes('speech')) {
+      if (this.input.includes('speech') && this.listenDuringPrompt) {
         await this._initSpeech(cs, ep);
         this._startTranscribing(ep);
         updateSpeechCredentialLastUsed(this.sttCredentials.speech_credential_sid)
           .catch(() => {/*already logged error */});
       }
 
-      if (this.input.includes('digits')) {
+      if (this.input.includes('digits') || this.dtmfBargein) {
         ep.on('dtmf', this._onDtmf.bind(this, cs, ep));
       }
 
@@ -125,17 +161,33 @@ class TaskGather extends Task {
     super.kill(cs);
     this._killAudio(cs);
     this.ep.removeAllListeners('dtmf');
+    clearTimeout(this.interDigitTimer);
     this._resolve('killed');
   }
 
   _onDtmf(cs, ep, evt) {
     this.logger.debug(evt, 'TaskGather:_onDtmf');
-    if (evt.dtmf === this.finishOnKey) this._resolve('dtmf-terminator-key');
+    clearTimeout(this.interDigitTimer);
+    let resolved = false;
+    if (this.dtmfBargein) this._killAudio(cs);
+    if (evt.dtmf === this.finishOnKey && this.input.includes('digits')) {
+      resolved = true;
+      this._resolve('dtmf-terminator-key');
+    }
     else {
       this.digitBuffer += evt.dtmf;
-      if (this.digitBuffer.length === this.numDigits) this._resolve('dtmf-num-digits');
+      const len = this.digitBuffer.length;
+      if (len === this.numDigits || len === this.maxDigits) {
+        resolved = true;
+        this._resolve('dtmf-num-digits');
+      }
+    }
+    if (!resolved && this.interDigitTimeout > 0 && this.digitBuffer.length >= this.minDigits) {
+      /* start interDigitTimer */
+      const ms = this.interDigitTimeout * 1000;
+      this.logger.debug(`starting interdigit timer of ${ms}`);
+      this.interDigitTimer = setTimeout(() => this._resolve('dtmf-interdigit-timeout'), ms);
     }
-    this._killAudio(cs);
   }
 
   async _initSpeech(cs, ep) {
@@ -207,7 +259,7 @@ class TaskGather extends Task {
     ep.startTranscription({
       vendor: this.vendor,
       locale: this.language,
-      interim: this.partialResultCallback ? true : false,
+      interim: this.partialResultCallback || this.bargein,
     }).catch((err) => {
       const {writeAlerts, AlertType} = this.cs.srf.locals;
       this.logger.error(err, 'TaskGather:_startTranscribing error');
@@ -249,23 +301,47 @@ class TaskGather extends Task {
   _onTranscription(cs, ep, evt) {
     if ('aws' === this.vendor && Array.isArray(evt) && evt.length > 0) evt = evt[0];
     if ('microsoft' === this.vendor) {
-      const nbest = evt.NBest;
+      const final = evt.RecognitionStatus === 'Success';
-      const newEvent = {
+      if (final) {
-        is_final: evt.RecognitionStatus === 'Success',
+        const nbest = evt.NBest;
-        alternatives: [
+        evt = {
-          {
+          is_final: true,
-            confidence: nbest[0].Confidence,
+          alternatives: [
-            transcript: nbest[0].Display
+            {
-          }
+              confidence: nbest[0].Confidence,
-        ]
+              transcript: nbest[0].Display
-      };
+            }
-      evt = newEvent;
+          ]
+        };
+      }
+      else {
+        evt = {
+          is_final: false,
+          alternatives: [
+            {
+              transcript: evt.Text
+            }
+          ]
+        };
+      }
     }
-    this.logger.debug(evt, 'TaskGather:_onTranscription');
     if (evt.is_final) this._resolve('speech', evt);
-    else if (this.partialResultHook) {
+    else {
-      this.cs.requestor.request('verb:hook', this.partialResultHook,  Object.assign({speech: evt}, this.cs.callInfo))
+      /* google has a measure of stability:
-        .catch((err) => this.logger.info(err, 'GatherTask:_onTranscription error'));
+        https://cloud.google.com/speech-to-text/docs/basics#streaming_responses
+        others do not.
+      */
+      const isStableEnough = typeof evt.stability === 'undefined' || evt.stability > GATHER_STABILITY_THRESHOLD;
+
+      if (this.bargein && isStableEnough &&
+        evt.alternatives[0].transcript.split(' ').length >= this.minBargeinWordCount) {
+        this.logger.debug('Gather:_onTranscription - killing audio due to speech bargein');
+        this._killAudio(cs);
+      }
+      if (this.partialResultHook) {
+        this.cs.requestor.request(this.partialResultHook,  Object.assign({speech: evt}, this.cs.callInfo))
+          .catch((err) => this.logger.info(err, 'GatherTask:_onTranscription error'));
+      }
     }
   }
   _onEndOfUtterance(cs, ep) {
@@ -283,6 +359,7 @@ class TaskGather extends Task {
     if (this.resolved) return;
     this.resolved = true;
     this.logger.debug(`TaskGather:resolve with reason ${reason}`);
+    clearTimeout(this.interDigitTimer);
 
     if (this.ep && this.ep.connected) {
       this.ep.stopTranscription({vendor: this.vendor})

lib/tasks/say.js

@@ -14,6 +14,14 @@ class TaskSay extends Task {
 
   get name() { return TaskName.Say; }
 
+  get summary() {
+    for (let i = 0; i < this.text.length; i++) {
+      if (this.text[i].startsWith('silence_stream')) continue;
+      return `${this.name}{text=${this.text[i].slice(0, 15)}${this.text[i].length > 15 ? '...' : ''}}`;
+    }
+    return this.text[0];
+  }
+
   async exec(cs, ep) {
     await super.exec(cs);
 
@@ -21,15 +29,20 @@ class TaskSay extends Task {
     const {updateSpeechCredentialLastUsed} = require('../utils/db-utils')(this.logger, srf);
     const {writeAlerts, AlertType, stats} = srf.locals;
     const {synthAudio} = srf.locals.dbHelpers;
-    const hasVerbLevelTts = this.synthesizer.vendor && this.synthesizer.vendor !== 'default';
+    const vendor = this.synthesizer.vendor && this.synthesizer.vendor !== 'default' ?
-    const vendor = hasVerbLevelTts ? this.synthesizer.vendor : cs.speechSynthesisVendor ;
+      this.synthesizer.vendor :
-    const language = hasVerbLevelTts ? this.synthesizer.language : cs.speechSynthesisLanguage ;
+      cs.speechSynthesisVendor;
-    const voice = hasVerbLevelTts ? this.synthesizer.voice : cs.speechSynthesisVoice ;
+    const language = this.synthesizer.language && this.synthesizer.language !== 'default' ?
+      this.synthesizer.language :
+      cs.speechSynthesisLanguage ;
+    const voice =  this.synthesizer.voice && this.synthesizer.voice !== 'default' ?
+      this.synthesizer.voice :
+      cs.speechSynthesisVoice;
     const engine = this.synthesizer.engine || 'standard';
     const salt = cs.callSid;
     const credentials = cs.getSpeechCredentials(vendor, 'tts');
 
-    this.logger.info({language, voice}, `Task:say - using vendor: ${vendor}`);
+    this.logger.info({vendor, language, voice}, 'TaskSay:exec');
     this.ep = ep;
     try {
       if (!credentials) {
@@ -80,7 +93,11 @@ class TaskSay extends Task {
             const {memberId, confName, confUuid} = cs;
             await this.playToConfMember(this.ep, memberId, confName, confUuid, filepath[segment]);
           }
-          else await ep.play(filepath[segment]);
+          else {
+            this.logger.debug(`Say:exec sending command to play file ${filepath[segment]}`);
+            await ep.play(filepath[segment]);
+            this.logger.debug(`Say:exec completed play file ${filepath[segment]}`);
+          }
         } while (!this.killed && ++segment < filepath.length);
       }
     } catch (err) {

lib/tasks/specs.json

@@ -98,8 +98,15 @@
       "finishOnKey": "string",
       "input": "array",
       "numDigits": "number",
+      "minDigits": "number",
+      "maxDigits": "number",
+      "interDigitTimeout": "number",
       "partialResultHook": "object|string",
       "speechTimeout": "number",
+      "listenDuringPrompt": "boolean",
+      "dtmfBargein": "boolean",
+      "bargein": "boolean",
+      "minBargeinWordCount": "number",
       "timeout": "number",
       "recognizer": "#recognizer",
       "play": "#play",

lib/tasks/task.js

@@ -42,6 +42,10 @@ class Task extends Emitter {
     return this.cs;
   }
 
+  get summary() {
+    return this.name;
+  }
+
   toJSON() {
     return this.data;
   }

lib/utils/summarize-tasks.js

@@ -1,3 +1,3 @@
 module.exports = function(tasks) {
-  return `[${tasks.map((t) => t.name).join(',')}]`;
+  return `[${tasks.map((t) => t.summary).join(',')}]`;
 };

lib/utils/ws-requestor.js

@@ -58,7 +58,7 @@ class WsRequestor extends BaseRequestor {
         const rtt = this._roundTrip(startAt);
         this.stats.histogram('app.hook.connect_time', rtt, ['hook_type:app']);
       } catch (err) {
-        this.logger.error({err}, 'WsRequestor:request - failed connecting');
+        this.logger.info({url, err}, 'WsRequestor:request - failed connecting');
         throw err;
       }
     }
@@ -137,11 +137,12 @@ class WsRequestor extends BaseRequestor {
         .once('ready', (ws) => {
           this.ws = ws;
           this.removeAllListeners('not-ready');
+          this.connections++;
           resolve();
         })
-        .once('not-ready', () => {
+        .once('not-ready', (err) => {
           this.removeAllListeners('ready');
-          reject();
+          reject(err);
         });
       const ws = new Websocket(this.url, ['ws.jambonz.org'], opts);
       this._setHandlers(ws);
@@ -158,9 +159,11 @@ class WsRequestor extends BaseRequestor {
   }
 
   _onError(err) {
-    this.logger.info({url: this.url, err}, 'WsRequestor:_onError');
+    if (this.connections > 0) {
-    if (this.connections > 0) this.emit('socket-closed');
+      this.logger.info({url: this.url, err}, 'WsRequestor:_onError');
-    this.emit('not-ready');
+      if (this.connections > 0) this.emit('socket-closed');
+    }
+    else this.emit('not-ready', err);
   }
 
   _onOpen(ws) {
@@ -170,8 +173,10 @@ class WsRequestor extends BaseRequestor {
   }
 
   _onClose() {
-    this.logger.info({url: this.url}, 'WsRequestor - socket closed unexpectedly from remote side');
+    if (this.connections > 0) {
-    this.emit('socket-closed');
+      this.logger.info({url: this.url}, 'WsRequestor - socket closed unexpectedly from remote side');
+      this.emit('socket-closed');
+    }
   }
 
   _onUnexpectedResponse(ws, req, res) {
@@ -182,7 +187,7 @@ class WsRequestor extends BaseRequestor {
       statusMessage: res.statusMessage
     }, 'WsRequestor - unexpected response');
     this.emit('connection-failure');
-    this.emit('not-ready');
+    this.emit('not-ready', new Error(`${res.statusCode} ${res.statusMessage}`));
   }
 
   _onSocketClosed() {