add startup logging

app.js

@@ -29,6 +29,12 @@ const {LifeCycleEvents, FS_UUID_SET_NAME, SystemState, FEATURE_SERVER} = require
 const installSrfLocals = require('./lib/utils/install-srf-locals');
 const createHttpListener = require('./lib/utils/http-listener');
 const healthCheck = require('@jambonz/http-health-check');
+const ProcessMonitor = require('./lib/utils/process-monitor');
+const monitor = new ProcessMonitor(logger);
+
+// Log startup
+monitor.logStartup();
+monitor.setupSignalHandlers();
 
 logger.on('level-change', (lvl, _val, prevLvl, _prevVal, instance) => {
   if (logger !== instance) {

lib/tasks/gather.js

@@ -368,6 +368,9 @@ class TaskGather extends SttTask {
 
   _onDtmf(cs, ep, evt) {
     this.logger.debug(evt, 'TaskGather:_onDtmf');
+    if (!this._timeoutTimer && this.timeout > 0) {
+      this._startTimer();
+    }
     clearTimeout(this.interDigitTimer);
     let resolved = false;
     if (this.dtmfBargein) {
@@ -696,6 +699,7 @@ class TaskGather extends SttTask {
 
   _startTimer() {
     if (0 === this.timeout) return;
+    this.logger.debug(`Starting timoutTimer of ${this.timeout}ms`);
     this._clearTimer();
     this._timeoutTimer = setTimeout(() => {
       if (this.isContinuousAsr) this._startAsrTimer();

lib/tasks/llm/llms/ultravox_s2s.js

@@ -218,7 +218,7 @@ class TaskLlmUltravox_S2S extends Task {
   async _onServerEvent(_ep, evt) {
     let endConversation = false;
     const type = evt.type;
-    this.logger.debug({evt}, 'TaskLlmUltravox_S2S:_onServerEvent');
+    //this.logger.debug({evt}, 'TaskLlmUltravox_S2S:_onServerEvent');
 
     /* server errors of some sort */
     if (type === 'error') {

lib/tasks/say.js

@@ -264,14 +264,11 @@ class TaskSay extends TtsTask {
           await this.playToConfMember(ep, memberId, confName, confUuid, filepath[segment]);
         }
         else {
-          let playbackId;
           const isStreaming = filepath[segment].startsWith('say:{');
           if (isStreaming) {
             const arr = /^say:\{.*\}\s*(.*)$/.exec(filepath[segment]);
-            if (arr) this.logger.debug(`Say:exec sending streaming tts request: ${arr[1].substring(0, 64)}..`);
-          }
-          else {
-            this.logger.debug(`Say:exec sending ${filepath[segment].substring(0, 64)}`);
+            if (arr) this.logger.debug(`Say:exec sending streaming tts request ${arr[1].substring(0, 64)}..`);
+            else this.logger.debug(`Say:exec sending ${filepath[segment].substring(0, 64)}`);
           }
 
           const onPlaybackStop = (evt) => {
@@ -283,10 +280,11 @@ class TaskSay extends TtsTask {
                * If we got a playback id on both the start and stop events, and they don't match,
                * then we must have received a playback-stop event for an earlier play request.
                */
-              const unmatchedResponse = (!!playbackId && !!evt.variable_tts_playback_id) &&
-                evt.variable_tts_playback_id !== playbackId;
+              const playbackId = this.getPlaybackId(segment);
+              // eslint-disable-next-line max-len
+              const unmatchedResponse = (!!playbackId && !!evt.variable_tts_playback_id) && evt.variable_tts_playback_id !== playbackId;
               if (unmatchedResponse) {
-                this.logger.info({currentPlaybackId: playbackId, stopPPlaybackId: evt.variable_tts_playback_id},
+                this.logger.info({currentPlaybackId: playbackId, stopPlaybackId: evt.variable_tts_playback_id},
                   'Say:exec discarding playback-stop for earlier play');
                 ep.once('playback-stop',  this._boundOnPlaybackStop);
 
@@ -358,9 +356,17 @@ class TaskSay extends TtsTask {
           };
           this._boundOnPlaybackStop = onPlaybackStop.bind(this);
 
-          ep.once('playback-start', (evt) => {
+          const onPlaybackStart = (evt) => {
             try {
-              playbackId = evt.variable_tts_playback_id;
+              const playbackId = this.getPlaybackId(segment);
+              // eslint-disable-next-line max-len
+              const unmatchedResponse = (!!playbackId && !!evt.variable_tts_playback_id) && evt.variable_tts_playback_id !== playbackId;
+              if (unmatchedResponse) {
+                this.logger.info({currentPlaybackId: playbackId, stopPlaybackId: evt.variable_tts_playback_id},
+                  'Say:exec playback-start - unmatched playback_id');
+                ep.once('playback-start',  this._boundOnPlaybackStart);
+                return;
+              }
               this.logger.debug({evt},
                 `Say got playback-start ${evt.variable_tts_playback_id ? evt.variable_tts_playback_id : ''}`);
               if (this.otelSpan) {
@@ -374,8 +380,11 @@ class TaskSay extends TtsTask {
             } catch (err) {
               this.logger.info({err}, 'Error handling playback-start event');
             }
-          });
+          };
+          this._boundOnPlaybackStart = onPlaybackStart.bind(this);
+
           ep.once('playback-stop',  this._boundOnPlaybackStop);
+          ep.once('playback-start',  this._boundOnPlaybackStart);
 
           // wait for playback-stop event received to confirm if the playback is successful
           this._playPromise = new Promise((resolve, reject) => {

lib/tasks/tts-task.js

@@ -3,6 +3,16 @@ const { TaskPreconditions } = require('../utils/constants');
 const { SpeechCredentialError } = require('../utils/error');
 const dbUtils = require('../utils/db-utils');
 
+const extractPlaybackId = (str) => {
+  // Match say:{...} and capture the content inside braces
+  const match = str.match(/say:\{([^}]*)\}/);
+  if (!match) return null;
+
+  // Look for playback_id=value within the captured content
+  const playbackMatch = match[1].match(/playback_id=([^,]*)/);
+  return playbackMatch ? playbackMatch[1] : null;
+};
+
 class TtsTask extends Task {
 
   constructor(logger, data, parentTask) {
@@ -22,6 +32,11 @@ class TtsTask extends Task {
     this.disableTtsCache = this.data.disableTtsCache;
     this.options = this.synthesizer.options || {};
     this.instructions = this.data.instructions;
+    this.playbackIds = [];
+  }
+
+  getPlaybackId(offset) {
+    return this.playbackIds[offset];
   }
 
   async exec(cs) {
@@ -280,6 +295,7 @@ class TtsTask extends Task {
             renderForCaching: preCache
           });
           if (!filePath.startsWith('say:')) {
+            this.playbackIds.push(null);
             this.logger.debug(`Say: file ${filePath}, served from cache ${servedFromCache}`);
             if (filePath) cs.trackTmpFile(filePath);
             if (this.otelSpan) {
@@ -309,7 +325,8 @@ class TtsTask extends Task {
             }
           }
           else {
-            this.logger.debug('Say: a streaming tts api will be used');
+            this.playbackIds.push(extractPlaybackId(filePath));
+            this.logger.debug({playbackIds: this.playbackIds}, 'Say: a streaming tts api will be used');
             const modifiedPath = filePath.replace('say:{', `say:{session-uuid=${ep.uuid},`);
             return modifiedPath;
           }

lib/utils/ws-requestor.js

@@ -293,7 +293,7 @@ class WsRequestor extends BaseRequestor {
 
       /* send the message */
       this.ws.send(JSON.stringify(obj), async() => {
-        this.logger.debug({obj}, `WsRequestor:request websocket: sent (${url})`);
+        if (obj.type !== 'llm:event') this.logger.debug({obj}, `WsRequestor:request websocket: sent (${url})`);
         // If session:reconnect is waiting for ack, hold here until ack to send queuedMsgs
         if (this._reconnectPromise) {
           try {

package-lock.json

@@ -15,7 +15,7 @@
         "@jambonz/http-health-check": "^0.0.1",
         "@jambonz/mw-registrar": "^0.2.7",
         "@jambonz/realtimedb-helpers": "^0.8.15",
-        "@jambonz/speech-utils": "^0.2.17",
+        "@jambonz/speech-utils": "^0.2.22",
         "@jambonz/stats-collector": "^0.1.10",
         "@jambonz/time-series": "^0.2.14",
         "@jambonz/verb-specifications": "^0.0.113",
@@ -1376,10 +1376,9 @@
       }
     },
     "node_modules/@jambonz/speech-utils": {
-      "version": "0.2.17",
-      "resolved": "https://registry.npmjs.org/@jambonz/speech-utils/-/speech-utils-0.2.17.tgz",
-      "integrity": "sha512-YcBq8bOvo5QfQJQXP4e2N0sCPqkoW0jNM4eHhspJotJc7V9DB3T5VVA6SGUsDXDZUwyT0JPI3Tx+xof02eWQ2Q==",
-      "license": "MIT",
+      "version": "0.2.22",
+      "resolved": "https://registry.npmjs.org/@jambonz/speech-utils/-/speech-utils-0.2.22.tgz",
+      "integrity": "sha512-heSKhoIEAbIjmzwo4CKLkpClGBYrLEo7tud5V0kj2Su3MmgBjCNkPh2WVrP0Qj4Ix8ROKXLASzApkrL60zwNYg==",
       "dependencies": {
         "23": "^0.0.0",
         "@aws-sdk/client-polly": "^3.496.0",

package.json

@@ -31,7 +31,7 @@
     "@jambonz/http-health-check": "^0.0.1",
     "@jambonz/mw-registrar": "^0.2.7",
     "@jambonz/realtimedb-helpers": "^0.8.15",
-    "@jambonz/speech-utils": "^0.2.17",
+    "@jambonz/speech-utils": "^0.2.22",
     "@jambonz/stats-collector": "^0.1.10",
     "@jambonz/time-series": "^0.2.14",
     "@jambonz/verb-specifications": "^0.0.113",