From d310ba0ed13330b1d94e34cb91ec182721689055 Mon Sep 17 00:00:00 2001 From: Dave Horton Date: Wed, 9 Apr 2025 15:36:58 -0400 Subject: [PATCH] reduce verbosity of logging (#1145) --- lib/session/call-session.js | 41 +++++++++++++++--------------- lib/tasks/listen.js | 2 +- lib/tasks/llm/llms/ultravox_s2s.js | 19 +++++++------- lib/tasks/tts-task.js | 4 +-- 4 files changed, 33 insertions(+), 33 deletions(-) diff --git a/lib/session/call-session.js b/lib/session/call-session.js index 8a16689f..f847ac5f 100644 --- a/lib/session/call-session.js +++ b/lib/session/call-session.js @@ -962,7 +962,7 @@ class CallSession extends Emitter { (type === 'tts' && credential.use_for_tts) || (type === 'stt' && credential.use_for_stt) )) { - this.logger.info( + this.logger.debug( `${type}: ${credential.vendor} ${credential.label ? `, label: ${credential.label}` : ''} `); if ('google' === vendor) { if (type === 'tts' && !credential.tts_tested_ok || @@ -1459,7 +1459,7 @@ class CallSession extends Emitter { } if (tasks) { const t = normalizeJambones(this.logger, tasks).map((tdata) => makeTask(this.logger, tdata)); - this.logger.info({tasks: listTaskNames(t)}, 'CallSession:_lccCallHook new task list'); + this.logger.debug({tasks: listTaskNames(t)}, 'CallSession:_lccCallHook new task list'); this.replaceApplication(t); if (this.wakeupResolver) { //this.logger.debug({resolution}, 'CallSession:_onCommand - got commands, waking up..'); @@ -1726,10 +1726,10 @@ Duration=${duration} ` this.currentTask.ep : this.ep; const db = parseDecibels(opts); - this.logger.info(`_lccBoostAudioSignal: boosting audio signal by ${db} dB`); + this.logger.debug(`_lccBoostAudioSignal: boosting audio signal by ${db} dB`); const args = [ep.uuid, 'setGain', db]; const response = await ep.api('uuid_dub', args); - this.logger.info({response}, '_lccBoostAudioSignal: response from freeswitch'); + this.logger.debug({response}, '_lccBoostAudioSignal: response from freeswitch'); } async _lccMediaPath(desiredPath) { @@ -1782,7 +1782,6 @@ Duration=${duration} ` let res; try { res = await this.ttsStreamingBuffer?.bufferTokens(tokens); - this.logger.info({id, res}, 'CallSession:_lccTtsTokens - tts:tokens-result'); } catch (err) { this.logger.info(err, 'CallSession:_lccTtsTokens'); } @@ -1917,7 +1916,7 @@ Duration=${duration} ` this.tasks = tasks; this.taskIdx = 0; this.stackIdx++; - this.logger.info({tasks: listTaskNames(tasks)}, + this.logger.debug({tasks: listTaskNames(tasks)}, `CallSession:replaceApplication reset with ${tasks.length} new tasks, stack depth is ${this.stackIdx}`); if (this.currentTask) { this.currentTask.kill(this, KillReason.Replaced); @@ -1932,7 +1931,7 @@ Duration=${duration} ` kill(onBackgroundGatherBargein = false) { if (this.isConfirmCallSession) this.logger.debug('CallSession:kill (ConfirmSession)'); - else this.logger.info('CallSession:kill'); + else this.logger.debug('CallSession:kill'); this._endVerbHookSpan(); if (this.currentTask) { this.currentTask.kill(this); @@ -1997,7 +1996,7 @@ Duration=${duration} ` task.synthesizer.label : this.speechSynthesisLabel; - this.logger.info({vendor, language, voice, label}, + this.logger.debug({vendor, language, voice, label}, 'CallSession:_preCacheAudio - precaching audio for future prompt'); task._synthesizeWithSpecificVendor(this, this.ep, {vendor, language, voice, label, preCache: true}) .catch((err) => this.logger.error(err, 'CallSession:_preCacheAudio - error precaching audio')); @@ -2067,7 +2066,7 @@ Duration=${duration} ` } async _onCommand({msgid, command, call_sid, queueCommand, tool_call_id, data}) { - this.logger.info({msgid, command, queueCommand, data}, 'CallSession:_onCommand - received command'); + this.logger.debug({msgid, command, queueCommand, data}, 'CallSession:_onCommand - received command'); let resolution; switch (command) { case 'redirect': @@ -2076,18 +2075,18 @@ Duration=${duration} ` const t = normalizeJambones(this.logger, data) .map((tdata) => makeTask(this.logger, tdata)); if (!queueCommand) { - this.logger.info({tasks: listTaskNames(t)}, 'CallSession:_onCommand new task list'); + this.logger.debug({tasks: listTaskNames(t)}, 'CallSession:_onCommand new task list'); this.replaceApplication(t); } else if (JAMBONES_INJECT_CONTENT) { if (JAMBONES_EAGERLY_PRE_CACHE_AUDIO) this._preCacheAudio(t); this._injectTasks(t); - this.logger.info({tasks: listTaskNames(this.tasks)}, 'CallSession:_onCommand - updated task list'); + this.logger.debug({tasks: listTaskNames(this.tasks)}, 'CallSession:_onCommand - updated task list'); } else { if (JAMBONES_EAGERLY_PRE_CACHE_AUDIO) this._preCacheAudio(t); this.tasks.push(...t); - this.logger.info({tasks: listTaskNames(this.tasks)}, 'CallSession:_onCommand - updated task list'); + this.logger.debug({tasks: listTaskNames(this.tasks)}, 'CallSession:_onCommand - updated task list'); } resolution = {reason: 'received command, new tasks', queue: queueCommand, command}; resolution.command = listTaskNames(t); @@ -2607,7 +2606,7 @@ Duration=${duration} ` if (json && Array.isArray(json)) { const tasks = normalizeJambones(this.logger, json).map((tdata) => makeTask(this.logger, tdata)); if (tasks && tasks.length > 0) { - this.logger.info('CallSession:handleRefer received REFER, get new tasks'); + this.logger.debug('CallSession:handleRefer received REFER, get new tasks'); this.replaceApplication(tasks); if (this.wakeupResolver) { this.wakeupResolver({reason: 'CallSession: referHook new taks'}); @@ -2654,14 +2653,14 @@ Duration=${duration} ` if (typeof this.queueEventHookRequestor === 'undefined') { const pp = this._pool.promise(); try { - this.logger.info({accountSid: this.accountSid}, 'performQueueWebhook: looking up account'); + this.logger.debug({accountSid: this.accountSid}, 'performQueueWebhook: looking up account'); const [r] = await pp.query(sqlRetrieveQueueEventHook, [this.accountSid]); if (0 === r.length) { this.logger.info({accountSid: this.accountSid}, 'performQueueWebhook: no webhook provisioned'); this.queueEventHookRequestor = null; } else { - this.logger.info({accountSid: this.accountSid, webhook: r[0]}, 'performQueueWebhook: webhook found'); + this.logger.debug({accountSid: this.accountSid, webhook: r[0]}, 'performQueueWebhook: webhook found'); this.queueEventHookRequestor = new HttpRequestor(this.logger, this.accountSid, r[0], this.webhook_secret); this.queueEventHook = r[0]; @@ -2675,7 +2674,7 @@ Duration=${duration} ` /* send webhook */ const params = {...obj, ...this.callInfo.toJSON()}; - this.logger.info({accountSid: this.accountSid, params}, 'performQueueWebhook: sending webhook'); + this.logger.debug({accountSid: this.accountSid, params}, 'performQueueWebhook: sending webhook'); this.queueEventHookRequestor.request('queue:status', this.queueEventHook, params) .catch((err) => { this.logger.info({err, accountSid: this.accountSid, obj}, 'Error sending queue notification event'); @@ -2810,7 +2809,7 @@ Duration=${duration} ` async handleReinviteAfterMediaReleased(req, res) { assert(this.dlg && this.dlg.connected && !this.ep); const sdp = await this.dlg.modify(req.body); - this.logger.info({sdp}, 'CallSession:handleReinviteAfterMediaReleased - reinvite to A leg returned sdp'); + this.logger.debug({sdp}, 'CallSession:handleReinviteAfterMediaReleased - reinvite to A leg returned sdp'); res.send(200, {body: sdp}); } @@ -2891,7 +2890,7 @@ Duration=${duration} ` // if final transcription is received but endpoint is already closed, // freeswitch module will not be able to send the transcription - this.logger.info('callSession:_configMsEndpoint -' + + this.logger.debug('callSession:_configMsEndpoint -' + ' transcribe task, wait for some time before destroy'); await sleepFor(JAMBONES_TRANSCRIBE_EP_DESTROY_DELAY_MS); } @@ -2945,7 +2944,7 @@ Duration=${duration} ` _awaitCommandsOrHangup() { assert(!this.wakeupResolver); return new Promise((resolve, reject) => { - this.logger.info('_awaitCommandsOrHangup - waiting...'); + this.logger.debug('_awaitCommandsOrHangup - waiting...'); this.wakeupResolver = resolve; if (this._actionHookDelayProcessor) { @@ -2965,7 +2964,7 @@ Duration=${duration} ` this.ep.play(this.fillerNoise.url); this.ep.once('playback-start', (evt) => { if (evt.file === this.fillerNoise.url && !this._isPlayingFillerNoise) { - this.logger.info('CallSession:_awaitCommandsOrHangup - filler noise started'); + this.logger.debug('CallSession:_awaitCommandsOrHangup - filler noise started'); this.ep.api('uuid_break', this.ep.uuid) .catch((err) => this.logger.info(err, 'Error killing filler noise')); } @@ -2976,7 +2975,7 @@ Duration=${duration} ` _clearTasks(backgroundGather, evt) { if (this.requestor instanceof WsRequestor && !backgroundGather.cleared) { - this.logger.info({evt}, 'CallSession:_clearTasks on event from background gather'); + this.logger.debug({evt}, 'CallSession:_clearTasks on event from background gather'); try { backgroundGather.cleared = true; this.kill(true); diff --git a/lib/tasks/listen.js b/lib/tasks/listen.js index d89844c3..5e5d5e97 100644 --- a/lib/tasks/listen.js +++ b/lib/tasks/listen.js @@ -221,7 +221,7 @@ class TaskListen extends Task { } } _onConnect(ep) { - this.logger.debug('TaskListen:_onConnect'); + this.logger.info('TaskListen:_onConnect'); } _onConnectFailure(ep, evt) { this.logger.info(evt, 'TaskListen:_onConnectFailure'); diff --git a/lib/tasks/llm/llms/ultravox_s2s.js b/lib/tasks/llm/llms/ultravox_s2s.js index 623258c9..2624fe6d 100644 --- a/lib/tasks/llm/llms/ultravox_s2s.js +++ b/lib/tasks/llm/llms/ultravox_s2s.js @@ -85,10 +85,10 @@ class TaskLlmUltravox_S2S extends Task { }); const data = await body.json(); if (statusCode !== 201 || !data?.joinUrl) { - this.logger.error({statusCode, data}, 'Ultravox Error registering call'); + this.logger.info({statusCode, data}, 'Ultravox Error registering call'); throw new Error(`Ultravox Error registering call: ${data.message}`); } - this.logger.info({joinUrl: data.joinUrl}, 'Ultravox Call registered'); + this.logger.debug({joinUrl: data.joinUrl}, 'Ultravox Call registered'); return data; } @@ -120,7 +120,7 @@ class TaskLlmUltravox_S2S extends Task { ...data }); } catch (err) { - this.logger.error({err}, 'TaskLlmUltraVox_S2S:_startListening'); + this.logger.info({err}, 'TaskLlmUltraVox_S2S:_startListening - Error sending createCall'); this.notifyTaskDone(); } } @@ -148,7 +148,7 @@ class TaskLlmUltravox_S2S extends Task { } _onConnect(ep) { - this.logger.debug('TaskLlmUltravox_S2S:_onConnect'); + this.logger.info('TaskLlmUltravox_S2S:_onConnect'); } _onConnectFailure(_ep, evt) { this.logger.info(evt, 'TaskLlmUltravox_S2S:_onConnectFailure'); @@ -164,7 +164,7 @@ class TaskLlmUltravox_S2S extends Task { async _onServerEvent(_ep, evt) { let endConversation = false; const type = evt.type; - this.logger.info({evt}, 'TaskLlmUltravox_S2S:_onServerEvent'); + this.logger.debug({evt}, 'TaskLlmUltravox_S2S:_onServerEvent'); /* server errors of some sort */ if (type === 'error') { @@ -179,7 +179,7 @@ class TaskLlmUltravox_S2S extends Task { else if (type === 'client_tool_invocation') { this.logger.debug({evt}, 'TaskLlmUltravox_S2S:_onServerEvent - function_call'); if (!this.toolHook) { - this.logger.warn({evt}, 'TaskLlmUltravox_S2S:_onServerEvent - no toolHook defined!'); + this.logger.info({evt}, 'TaskLlmUltravox_S2S:_onServerEvent - no toolHook defined!'); } else { const {toolName: name, invocationId: call_id, parameters: args} = evt; @@ -221,13 +221,14 @@ class TaskLlmUltravox_S2S extends Task { if (!data.type || ![ 'input_text_message' ].includes(data.type)) { - this.logger.info({data}, 'TaskLlmUltravox_S2S:processLlmUpdate - invalid mid-call request'); + this.logger.info({data}, + 'TaskLlmUltravox_S2S:processLlmUpdate - invalid mid-call request, only input_text_message supported'); } else { await this._api(ep, [ep.uuid, ClientEvent, JSON.stringify(data)]); } } catch (err) { - this.logger.info({err}, 'TaskLlmUltravox_S2S:processLlmUpdate'); + this.logger.info({err, data}, 'TaskLlmUltravox_S2S:processLlmUpdate - Error processing LLM update'); } } @@ -243,7 +244,7 @@ class TaskLlmUltravox_S2S extends Task { await this._api(ep, [ep.uuid, ClientEvent, JSON.stringify(data)]); } } catch (err) { - this.logger.info({err}, 'TaskLlmUltravox_S2S:processToolOutput'); + this.logger.info({err, data}, 'TaskLlmUltravox_S2S:processToolOutput - Error processing tool output'); } } diff --git a/lib/tasks/tts-task.js b/lib/tasks/tts-task.js index a3f31285..57e329bf 100644 --- a/lib/tasks/tts-task.js +++ b/lib/tasks/tts-task.js @@ -137,7 +137,7 @@ class TtsTask extends Task { throw new Error(`vendor ${vendor} is not supported for tts streaming yet`); } } - this.logger.info({vendor, credentials, obj}, 'setTtsStreamingChannelVars'); + this.logger.debug({vendor, credentials, obj}, 'setTtsStreamingChannelVars'); await ep.set(obj); } @@ -231,7 +231,7 @@ class TtsTask extends Task { //cs.currentTtsVendor = vendor; if (!preCache && !this._disableTracing) - this.logger.info({vendor, language, voice, model: this.model}, 'TaskSay:exec'); + this.logger.debug({vendor, language, voice, model: this.model}, 'TaskSay:exec'); try { if (!credentials) { writeAlerts({