generate trace id before outdial so we can include it in custom header (#418)

* generate trace id before outdial so we can include it in custom header

* logging

* logging

* fix #420 race condition on rest outdial when ws is used

* revert unnecessary logging change

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

@@ -47,6 +47,11 @@ router.post('/', async(req, res) => {
     const application = req.body.application_sid ? await lookupAppBySid(req.body.application_sid) : null;
     const record_all_calls = account.record_all_calls || (application && application.record_all_calls);
     const recordOutputFormat = account.record_format || 'mp3';
+    const rootSpan = new RootSpan('rest-call', {
+      callSid,
+      accountSid,
+      ...(req.body?.application_sid && {'X-Application-Sid': req.body.application_sid})
+    });
 
     opts.headers = {
       ...opts.headers,
@@ -54,6 +59,7 @@ router.post('/', async(req, res) => {
       'X-Jambonz-FS-UUID': srf.locals.fsUUID,
       'X-Call-Sid': callSid,
       'X-Account-Sid': accountSid,
+      'X-Trace-ID': rootSpan.traceId,
       ...(req.body?.application_sid && {'X-Application-Sid': req.body.application_sid}),
       ...(restDial.fromHost && {'X-Preferred-From-Host': restDial.fromHost}),
       ...(record_all_calls && {'X-Record-All-Calls': recordOutputFormat})
@@ -194,7 +200,6 @@ router.post('/', async(req, res) => {
           /* ok our outbound INVITE is in flight */
 
           const tasks = [restDial];
-          const rootSpan = new RootSpan('rest-call', inviteReq);
           sipLogger = logger.child({
             callSid,
             callId: inviteReq.get('Call-ID'),
@@ -258,6 +263,7 @@ router.post('/', async(req, res) => {
           sipStatus: err.status,
           sipReason: err.reason
         });
+        cs.callGone = true;
       }
       else {
         if (cs) cs.emit('callStatusChange', {

lib/session/call-session.js

@@ -796,23 +796,15 @@ class CallSession extends Emitter {
         }
       }
 
-      if (0 === this.tasks.length && this.requestor instanceof WsRequestor && !this.callGone) {
+      if (0 === this.tasks.length &&
-        //let span;
+        this.requestor instanceof WsRequestor &&
+        !this.requestor.closedGracefully &&
+        !this.callGone
+      ) {
         try {
-          //const {span} = this.rootSpan.startChildSpan('waiting for commands');
-          //const {reason, queue, command} = await this._awaitCommandsOrHangup();
-          /*
-          span.setAttributes({
-            'completion.reason': reason,
-            'async.request.queue': queue,
-            'async.request.command': command
-          });
-          span.end();
-          */
           await this._awaitCommandsOrHangup();
           if (this.callGone) break;
         } catch (err) {
-          //span.end();
           this.logger.info(err, 'CallSession:exec - error waiting for new commands');
           break;
         }
@@ -1769,7 +1761,8 @@ class CallSession extends Emitter {
       // nice, call is in progress, good time to enable record
       await this.enableRecordAllCall();
     } else if (callStatus == CallStatus.Completed && this.isBackGroundListen) {
-      await this.stopBackgroundListen();
+      this.stopBackgroundListen().catch((err) => this.logger.error(
+        {err}, 'CallSession:_notifyCallStatusChange - error stopping background listen'));
     }
 
     /* race condition: we hang up at the same time as the caller */
@@ -1814,6 +1807,7 @@ class CallSession extends Emitter {
           username: JAMBONZ_RECORD_WS_USERNAME,
           password: JAMBONZ_RECORD_WS_PASSWORD
         },
+        disableBidirectionalAudio: true,
         mixType : 'stereo',
         passDtmf: true
       };

lib/session/rest-call-session.js

@@ -49,7 +49,6 @@ class RestCallSession extends CallSession {
    */
   _callerHungup() {
     if (this.restDialTask) {
-      this.logger.info('RestCallSession: releasing AMD');
       this.restDialTask.turnOffAmd();
     }
     this.callInfo.callTerminationBy = 'caller';

lib/tasks/listen.js

@@ -8,6 +8,7 @@ const DTMF_SPAN_NAME = 'dtmf';
 class TaskListen extends Task {
   constructor(logger, opts, parentTask) {
     super(logger, opts);
+    this.disableBidirectionalAudio = opts.disableBidirectionalAudio;
     this.preconditions = TaskPreconditions.Endpoint;
 
     [
@@ -154,7 +155,7 @@ class TaskListen extends Task {
     }
 
     /* support bi-directional audio */
-    if (!this.disableBiDirectionalAudio) {
+    if (!this.disableBidirectionalAudio) {
       ep.addCustomEventListener(ListenEvents.PlayAudio, this._onPlayAudio.bind(this, ep));
     }
     ep.addCustomEventListener(ListenEvents.KillAudio, this._onKillAudio.bind(this, ep));

lib/tasks/rest_dial.js

@@ -63,12 +63,13 @@ class TaskRestDial extends Task {
     this.canCancel = false;
     const cs = this.callSession;
     cs.setDialog(dlg);
+    this.logger.debug('TaskRestDial:_onConnect - call connected');
 
     try {
       const b3 = this.getTracingPropagation();
       const httpHeaders = b3 && {b3};
       const params = {
-        ...cs.callInfo,
+        ...(cs.callInfo.toJSON()),
         defaults: {
           synthesizer: {
             vendor: cs.speechSynthesisVendor,
@@ -90,8 +91,10 @@ class TaskRestDial extends Task {
       }
       let tasks;
       if (this.app_json) {
+        this.logger.debug('TaskRestDial: using app_json from task data');
         tasks = JSON.parse(this.app_json);
       } else {
+        this.logger.debug({call_hook: this.call_hook}, 'TaskRestDial: retrieving application');
         tasks = await cs.requestor.request('session:new', this.call_hook, params, httpHeaders);
       }
       if (tasks && Array.isArray(tasks)) {

lib/tasks/transcribe.js

@@ -1,4 +1,5 @@
 const Task = require('./task');
+const assert = require('assert');
 const {
   TaskName,
   TaskPreconditions,
@@ -56,6 +57,12 @@ class TaskTranscribe extends Task {
     this._sonioxTranscripts = [];
 
     this.childSpan = [null, null];
+
+    // Continuos asr timeout
+    this.asrTimeout = typeof this.data.recognizer.asrTimeout === 'number' ? this.data.recognizer.asrTimeout * 1000 : 0;
+    this.isContinuousAsr = this.asrTimeout > 0;
+    /* buffer speech for continuous asr */
+    this._bufferedTranscripts = [];
   }
 
   get name() { return TaskName.Transcribe; }
@@ -234,7 +241,19 @@ class TaskTranscribe extends Task {
           this._onVadDetected.bind(this, cs, ep));
         break;
       default:
-        throw new Error(`Invalid vendor ${this.vendor}`);
+        if (this.vendor.startsWith('custom:')) {
+          this.bugname = `${this.vendor}_transcribe`;
+          ep.addCustomEventListener(JambonzTranscriptionEvents.Transcription, this._onTranscription.bind(this, cs, ep));
+          ep.addCustomEventListener(JambonzTranscriptionEvents.Connect, this._onJambonzConnect.bind(this, cs, ep));
+          ep.addCustomEventListener(JambonzTranscriptionEvents.ConnectFailure,
+            this._onJambonzConnectFailure.bind(this, cs, ep));
+          break;
+        }
+        else {
+          this.notifyError({ msg: 'ASR error', details:`Invalid vendor ${this.vendor}`});
+          this.notifyTaskDone();
+          throw new Error(`Invalid vendor ${this.vendor}`);
+        }
     }
 
     /* common handler for all stt engine errors */
@@ -296,6 +315,26 @@ class TaskTranscribe extends Task {
       }
     }
 
+    if (this.isContinuousAsr && evt.is_final) {
+      this._bufferedTranscripts.push(evt);
+      this._startAsrTimer(channel);
+    } else {
+      await this._resolve(channel, evt);
+    }
+  }
+
+  _compileTranscripts() {
+    assert(this._bufferedTranscripts.length);
+    const evt = this._bufferedTranscripts[0];
+    let t = '';
+    for (const a of this._bufferedTranscripts) {
+      t += ` ${a.alternatives[0].transcript}`;
+    }
+    evt.alternatives[0].transcript = t.trim();
+    return evt;
+  }
+
+  async _resolve(channel, evt) {
     /* we've got a transcript, so end the otel child span for this channel */
     if (this.childSpan[channel - 1] && this.childSpan[channel - 1].span) {
       this.childSpan[channel - 1].span.setAttributes({
@@ -408,6 +447,24 @@ class TaskTranscribe extends Task {
     this.notifyTaskDone();
   }
 
+  _onJambonzConnect(_cs, _ep) {
+    this.logger.debug('TaskTranscribe:_onJambonzConnect');
+  }
+
+  _onJambonzConnectFailure(cs, _ep, evt) {
+    const {reason} = evt;
+    const {writeAlerts, AlertType} = cs.srf.locals;
+    this.logger.info({evt}, 'TaskTranscribe:_onJambonzConnectFailure');
+    writeAlerts({
+      account_sid: cs.accountSid,
+      alert_type: AlertType.STT_FAILURE,
+      message: `Failed connecting to ${this.vendor} speech recognizer: ${reason}`,
+      vendor: this.vendor,
+    }).catch((err) => this.logger.info({err}, 'Error generating alert for jambonz custom connection failure'));
+    this.notifyError({msg: 'ASR error', details:`Failed connecting to speech vendor ${this.vendor}: ${reason}`});
+    this.notifyTaskDone();
+  }
+
   _onIbmConnect(_cs, _ep) {
     this.logger.debug('TaskTranscribe:_onIbmConnect');
   }
@@ -455,7 +512,22 @@ class TaskTranscribe extends Task {
     this.notifyError({msg: 'ASR error', details:`Custom speech vendor ${this.vendor} error: ${evt.error}`});
   }
 
+  _startAsrTimer(channel) {
+    assert(this.isContinuousAsr);
+    this._clearAsrTimer(channel);
+    this._asrTimer = setTimeout(() => {
+      this.logger.debug(`TaskTranscribe:_startAsrTimer - asr timer went off for channel: ${channel}`);
+      const evt = this._compileTranscripts();
+      this._bufferedTranscripts = [];
+      this._resolve(channel, evt);
+    }, this.asrTimeout);
+    this.logger.debug(`TaskTranscribe:_startAsrTimer: set for ${this.asrTimeout}ms for channel ${channel}`);
+  }
 
+  _clearAsrTimer(channel) {
+    if (this._asrTimer) clearTimeout(this._asrTimer);
+    this._asrTimer = null;
+  }
 }
 
 module.exports = TaskTranscribe;

lib/utils/call-tracer.js

@@ -2,17 +2,24 @@ const {context, trace} = require('@opentelemetry/api');
 const {Dialog} = require('drachtio-srf');
 class RootSpan {
   constructor(callType, req) {
-    let tracer, callSid, linkedSpanId;
+    const {srf} = require('../../');
+    const tracer = srf.locals.otel.tracer;
+    let callSid, accountSid, applicationSid, linkedSpanId;
 
     if (req instanceof Dialog) {
       const dlg = req;
-      tracer = dlg.srf.locals.otel.tracer;
       callSid = dlg.callSid;
       linkedSpanId = dlg.linkedSpanId;
     }
-    else {
+    else if (req.srf) {
-      tracer = req.srf.locals.otel.tracer;
       callSid = req.locals.callSid;
+      accountSid = req.get('X-Account-Sid'),
+      applicationSid = req.locals.application_sid;
+    }
+    else {
+      callSid = req.callSid;
+      accountSid = req.accountSid;
+      applicationSid = req.applicationSid;
     }
     this._span = tracer.startSpan(callType || 'incoming-call');
     if (req instanceof Dialog) {
@@ -22,13 +29,20 @@ class RootSpan {
         callId: dlg.sip.callId
       });
     }
+    else if (req.srf) {
+      this._span.setAttributes({
+        callSid,
+        accountSid,
+        applicationSid,
+        callId: req.get('Call-ID'),
+        externalCallId: req.get('X-CID')
+      });
+    }
     else {
       this._span.setAttributes({
         callSid,
-        accountSid: req.get('X-Account-Sid'),
+        accountSid,
-        applicationSid: req.locals.application_sid,
+        applicationSid
-        callId: req.get('Call-ID'),
-        externalCallId: req.get('X-CID')
       });
     }
 

lib/utils/ws-requestor.js

@@ -43,6 +43,7 @@ class WsRequestor extends BaseRequestor {
   async request(type, hook, params, httpHeaders = {}) {
     assert(HookMsgTypes.includes(type));
     const url = hook.url || hook;
+    const wantsAck = !['call:status', 'verb:status', 'jambonz:error'].includes(type);
 
     if (this.maliciousClient) {
       this.logger.info({url: this.url}, 'WsRequestor:request - discarding msg to malicious client');
@@ -73,11 +74,19 @@ class WsRequestor extends BaseRequestor {
       if (this.connectInProgress) {
         this.logger.debug(
           `WsRequestor:request(${this.id}) - queueing ${type} message since we are connecting`);
-        this.queuedMsg.push({type, hook, params, httpHeaders});
+        if (wantsAck) {
+          const p = new Promise((resolve, reject) => {
+            this.queuedMsg.push({type, hook, params, httpHeaders, promise: {resolve, reject}});
+          });
+          return p;
+        }
+        else {
+          this.queuedMsg.push({type, hook, params, httpHeaders});
+        }
         return;
       }
       this.connectInProgress = true;
-      this.logger.debug(`WsRequestor:request(${this.id}) - connecting since we do not have a connection`);
+      this.logger.debug(`WsRequestor:request(${this.id}) - connecting since we do not have a connection for ${type}`);
       if (this.connections >= MAX_RECONNECTS) {
         return Promise.reject(`max attempts connecting to ${this.url}`);
       }
@@ -116,9 +125,14 @@ class WsRequestor extends BaseRequestor {
 
     const sendQueuedMsgs = () => {
       if (this.queuedMsg.length > 0) {
-        for (const {type, hook, params, httpHeaders} of this.queuedMsg) {
+        for (const {type, hook, params, httpHeaders, promise} of this.queuedMsg) {
           this.logger.debug(`WsRequestor:request - preparing queued ${type} for sending`);
-          setImmediate(this.request.bind(this, type, hook, params, httpHeaders));
+          if (promise) {
+            this.request(type, hook, params, httpHeaders)
+              .then((res) => promise.resolve(res))
+              .catch((err) => promise.reject(err));
+          }
+          else setImmediate(this.request.bind(this, type, hook, params, httpHeaders));
         }
         this.queuedMsg.length = 0;
       }
@@ -137,7 +151,7 @@ class WsRequestor extends BaseRequestor {
     }
 
     /* simple notifications */
-    if (['call:status', 'verb:status', 'jambonz:error'].includes(type) || reconnectingWithoutAck) {
+    if (!wantsAck || reconnectingWithoutAck) {
       this.ws?.send(JSON.stringify(obj), () => {
         this.logger.debug({obj}, `WsRequestor:request websocket: sent (${url})`);
         sendQueuedMsgs();

package-lock.json

@@ -14,8 +14,8 @@
         "@jambonz/db-helpers": "^0.9.1",
         "@jambonz/http-health-check": "^0.0.1",
         "@jambonz/realtimedb-helpers": "^0.8.6",
-        "@jambonz/speech-utils": "^0.0.18",
+        "@jambonz/speech-utils": "^0.0.19",
-        "@jambonz/stats-collector": "^0.1.8",
+        "@jambonz/stats-collector": "^0.1.9",
         "@jambonz/time-series": "^0.2.8",
         "@jambonz/verb-specifications": "^0.0.26",
         "@opentelemetry/api": "^1.4.0",
@@ -2983,9 +2983,9 @@
       }
     },
     "node_modules/@jambonz/speech-utils": {
-      "version": "0.0.18",
+      "version": "0.0.19",
-      "resolved": "https://registry.npmjs.org/@jambonz/speech-utils/-/speech-utils-0.0.18.tgz",
+      "resolved": "https://registry.npmjs.org/@jambonz/speech-utils/-/speech-utils-0.0.19.tgz",
-      "integrity": "sha512-UoX1sPV/kDUBp4uiivbFftpn9nx6G9rmspneszrksnSWERp0SP09yL6rvEFFTDMvFmK2ivP6TIMRywlExO4OQg==",
+      "integrity": "sha512-uVwt4cCQkNhRDDPK0BHgI9Zn+bXoqQdtK8kjj3dbqPAOO3FlMTWxA2ZWJoglzZShQUNzpEg3CLcVTAGNnJHP2Q==",
       "dependencies": {
         "@aws-sdk/client-polly": "^3.359.0",
         "@google-cloud/text-to-speech": "^4.2.1",
@@ -3001,9 +3001,9 @@
       }
     },
     "node_modules/@jambonz/stats-collector": {
-      "version": "0.1.8",
+      "version": "0.1.9",
-      "resolved": "https://registry.npmjs.org/@jambonz/stats-collector/-/stats-collector-0.1.8.tgz",
+      "resolved": "https://registry.npmjs.org/@jambonz/stats-collector/-/stats-collector-0.1.9.tgz",
-      "integrity": "sha512-PadBKTmcphU7bZI7pVr4awhoIi+DMLw7An6AGE0GGsLCn2x0IGnxr9k47gI4Bk3OaSF6N7RyVLEAMkJfr24l8Q==",
+      "integrity": "sha512-JNRBaHQ47pWsXydj4gUp7zc64/0pM89a6E9pA8uQ15l1KxPGYYTrNRdone5aJqLTFOoPl3tYeF1kXj+3nU1nEA==",
       "dependencies": {
         "debug": "^4.3.2",
         "hot-shots": "^8.5.0"
@@ -12949,9 +12949,9 @@
       }
     },
     "@jambonz/speech-utils": {
-      "version": "0.0.18",
+      "version": "0.0.19",
-      "resolved": "https://registry.npmjs.org/@jambonz/speech-utils/-/speech-utils-0.0.18.tgz",
+      "resolved": "https://registry.npmjs.org/@jambonz/speech-utils/-/speech-utils-0.0.19.tgz",
-      "integrity": "sha512-UoX1sPV/kDUBp4uiivbFftpn9nx6G9rmspneszrksnSWERp0SP09yL6rvEFFTDMvFmK2ivP6TIMRywlExO4OQg==",
+      "integrity": "sha512-uVwt4cCQkNhRDDPK0BHgI9Zn+bXoqQdtK8kjj3dbqPAOO3FlMTWxA2ZWJoglzZShQUNzpEg3CLcVTAGNnJHP2Q==",
       "requires": {
         "@aws-sdk/client-polly": "^3.359.0",
         "@google-cloud/text-to-speech": "^4.2.1",
@@ -12967,9 +12967,9 @@
       }
     },
     "@jambonz/stats-collector": {
-      "version": "0.1.8",
+      "version": "0.1.9",
-      "resolved": "https://registry.npmjs.org/@jambonz/stats-collector/-/stats-collector-0.1.8.tgz",
+      "resolved": "https://registry.npmjs.org/@jambonz/stats-collector/-/stats-collector-0.1.9.tgz",
-      "integrity": "sha512-PadBKTmcphU7bZI7pVr4awhoIi+DMLw7An6AGE0GGsLCn2x0IGnxr9k47gI4Bk3OaSF6N7RyVLEAMkJfr24l8Q==",
+      "integrity": "sha512-JNRBaHQ47pWsXydj4gUp7zc64/0pM89a6E9pA8uQ15l1KxPGYYTrNRdone5aJqLTFOoPl3tYeF1kXj+3nU1nEA==",
       "requires": {
         "debug": "^4.3.2",
         "hot-shots": "^8.5.0"

package.json

@@ -28,8 +28,8 @@
     "@jambonz/db-helpers": "^0.9.1",
     "@jambonz/http-health-check": "^0.0.1",
     "@jambonz/realtimedb-helpers": "^0.8.6",
-    "@jambonz/speech-utils": "^0.0.18",
+    "@jambonz/speech-utils": "^0.0.19",
-    "@jambonz/stats-collector": "^0.1.8",
+    "@jambonz/stats-collector": "^0.1.9",
     "@jambonz/time-series": "^0.2.8",
     "@jambonz/verb-specifications": "^0.0.26",
     "@opentelemetry/api": "^1.4.0",

test/transcribe-tests.js

@@ -210,6 +210,44 @@ test('\'transcribe\' test - soniox', async(t) => {
     t.ok(obj.body.speech.alternatives[0].transcript.toLowerCase().startsWith('i\'d like to speak to customer support'),
       'transcribe: succeeds when using soniox credentials');
 
+    disconnect();
+  } catch (err) {
+    console.log(`error received: ${err}`);
+    disconnect();
+    t.error(err);
+  }
+});
+
+test('\'transcribe\' test - google with asrTimeout', async(t) => {
+  if (!GCP_JSON_KEY) {
+    t.pass('skipping google tests');
+    return t.end();
+  }
+  clearModule.all();
+  const {srf, disconnect} = require('../app');
+
+  try {
+    await connect(srf);
+    // GIVEN
+    let verbs = [
+      {
+        "verb": "transcribe",
+        "recognizer": {
+          "vendor": "google",
+          "hints": ["customer support", "sales", "human resources", "HR"],
+          "asrTimeout": 4
+        },
+        "transcriptionHook": "/transcriptionHook"
+      }
+    ];
+    let from = "gather_success";
+    await provisionCallHook(from, verbs);
+    // THEN
+    await sippUac('uac-gather-account-creds-success.xml', '172.38.0.10', from);
+    let obj = await getJSON(`http://127.0.0.1:3100/lastRequest/${from}_actionHook`);
+    t.ok(obj.body.speech.alternatives[0].transcript.toLowerCase().startsWith('i\'d like to speak to customer support'),
+      'transcribe: succeeds when using google credentials');
+
     disconnect();
   } catch (err) {
     console.log(`error received: ${err}`);