Skip to content

Commit 5e3f662

Browse files
TS426TS426
TS426
authored and
TS426
committed
feat(iadvize): add DEBUG logs for proactive message flow investigation
Add comprehensive DEBUG logging to trace the proactive message flow and help diagnose DERCBOT-1774 (Iadvize sync issues). Logs added in: - IadvizeConnector: send(), flush, sendProactiveMessage(), sendByGraphQL() - AbstractProactiveAnswerHandler: handle(), start/flush/end proactive - ConnectorQueue: add0(), sendNextAction() - TockBotBus: deferMessageSending() channel operations Also fix potential NPE with null-safe parameter handling in sendByGraphQL().
1 parent a40df97 commit 5e3f662

File tree

4 files changed

+174
-54
lines changed

4 files changed

+174
-54
lines changed

‎bot/connector-iadvize/src/main/kotlin/IadvizeConnector.kt‎

Lines changed: 122 additions & 49 deletions
Original file line numberDiff line numberDiff line change
@@ -304,14 +304,26 @@ class IadvizeConnector internal constructor(
304304
delayInMs: Long,
305305
) {
306306
val iadvizeCallback = callback as? IadvizeConnectorCallback
307+
val caller = Thread.currentThread().stackTrace.getOrNull(2)?.methodName ?: "unknown"
308+
309+
logger.debug {
310+
"send(): caller=$caller, proactiveEnabled=$proactiveAnswerEnabled, " +
311+
"lastAnswer=${(event as? Action)?.metadata?.lastAnswer}, " +
312+
"eventType=${event::class.simpleName}, " +
313+
"callbackNull=${iadvizeCallback == null}, " +
314+
"thread=${Thread.currentThread().name}"
315+
}
316+
307317
iadvizeCallback?.addAction(event, delayInMs)
308318

309-
// Send message proactively if this mode is already started
310319
if (proactiveAnswerEnabled) {
311320
flushProactiveConversation(callback, proactiveParameters)
312321
} else {
313322
if (event is Action && event.metadata.lastAnswer) {
323+
logger.debug { "send(): lastAnswer=true, calling answerWithResponse()" }
314324
iadvizeCallback?.answerWithResponse()
325+
} else {
326+
logger.debug { "send(): proactiveEnabled=false AND lastAnswer=false → NO ACTION" }
315327
}
316328
}
317329
}
@@ -320,12 +332,21 @@ class IadvizeConnector internal constructor(
320332
callback: ConnectorCallback,
321333
botBus: BotBus,
322334
): Boolean {
323-
// Set proactive answer mode, and save parameters
335+
logger.debug {
336+
"startProactiveConversation(): BEFORE proactiveEnabled=$proactiveAnswerEnabled, " +
337+
"metadata=${botBus.connectorData.metadata}, thread=${Thread.currentThread().name}"
338+
}
339+
324340
proactiveAnswerEnabled = true
325341
proactiveParameters = botBus.connectorData.metadata
326342

343+
logger.debug {
344+
"startProactiveConversation(): AFTER proactiveEnabled=$proactiveAnswerEnabled, " +
345+
"CONVERSATION_ID=${proactiveParameters[IadvizeConnectorMetadata.CONVERSATION_ID.name]}, " +
346+
"CHAT_BOT_ID=${proactiveParameters[IadvizeConnectorMetadata.CHAT_BOT_ID.name]}"
347+
}
348+
327349
if (!proactiveStartMessage.isNullOrBlank()) {
328-
// Send a RAG start message
329350
botBus.send(proactiveStartMessage)
330351
}
331352
(callback as? IadvizeConnectorCallback)?.answerWithResponse()
@@ -337,54 +358,84 @@ class IadvizeConnector internal constructor(
337358
parameters: Map<String, String>,
338359
) {
339360
val iadvizeCallback = callback as? IadvizeConnectorCallback
361+
val caller = Thread.currentThread().stackTrace.getOrNull(2)?.methodName ?: "unknown"
362+
363+
logger.debug {
364+
"flushProactiveConversation(): caller=$caller, actions.size=${iadvizeCallback?.actions?.size ?: "NULL"}, " +
365+
"callbackNull=${iadvizeCallback == null}, " +
366+
"CONVERSATION_ID=${parameters[IadvizeConnectorMetadata.CONVERSATION_ID.name]}, " +
367+
"CHAT_BOT_ID=${parameters[IadvizeConnectorMetadata.CHAT_BOT_ID.name]}, " +
368+
"thread=${Thread.currentThread().name}"
369+
}
370+
371+
if (iadvizeCallback?.actions?.isEmpty() == true) {
372+
logger.debug { "flushProactiveConversation(): EMPTY LIST - nothing to send" }
373+
}
374+
340375
iadvizeCallback?.actions?.forEach {
376+
logger.debug { "flushProactiveConversation(): adding to queue action=${it.action::class.simpleName}" }
341377
queue.add(it.action, it.delayInMs) { action ->
342378
sendProactiveMessage(iadvizeCallback, action, parameters)
343379
}
344380
}
345381
iadvizeCallback?.actions?.clear()
346382
}
347383

348-
/**
349-
* Send [Action] using GraphQL
350-
* @param callback the [IadvizeConnectorCallback]
351-
* @param action the action to send
352-
* @param parameters the key value map of parameters
353-
*/
354384
private fun sendProactiveMessage(
355385
callback: IadvizeConnectorCallback,
356386
action: Action,
357387
parameters: Map<String, String>,
358388
) {
389+
logger.debug {
390+
"sendProactiveMessage(): actionType=${action::class.simpleName}, " +
391+
"CONVERSATION_ID=${parameters[IadvizeConnectorMetadata.CONVERSATION_ID.name]}, " +
392+
"CHAT_BOT_ID=${parameters[IadvizeConnectorMetadata.CHAT_BOT_ID.name]}, " +
393+
"thread=${Thread.currentThread().name}"
394+
}
395+
396+
val conversationId = parameters[IadvizeConnectorMetadata.CONVERSATION_ID.name]
397+
val chatBotId = parameters[IadvizeConnectorMetadata.CHAT_BOT_ID.name]
398+
if (conversationId == null || chatBotId == null) {
399+
logger.debug { "sendProactiveMessage(): MISSING PARAMS - CONVERSATION_ID=$conversationId, CHAT_BOT_ID=$chatBotId" }
400+
}
401+
359402
when (action) {
360-
is SendSentenceWithFootnotes -> action.sendByGraphQL(parameters)
403+
is SendSentenceWithFootnotes -> {
404+
logger.debug { "sendProactiveMessage(): SendSentenceWithFootnotes -> sendByGraphQL()" }
405+
action.sendByGraphQL(parameters)
406+
}
361407
is SendSentence -> {
362408
if (action.messages.isEmpty()) {
363409
action.text?.let {
364-
// Simple message
365-
IadvizeMessage(TextPayload(it)).sendByGraphQL(
366-
parameters,
367-
callback,
368-
)
410+
logger.debug { "sendProactiveMessage(): SendSentence -> sendByGraphQL() text='${it.take(50)}...'" }
411+
IadvizeMessage(TextPayload(it)).sendByGraphQL(parameters, callback)
412+
} ?: run {
413+
logger.debug { "sendProactiveMessage(): SendSentence with text=null, NOTHING SENT" }
369414
}
370415
} else {
371-
// Complex message
416+
logger.debug { "sendProactiveMessage(): SendSentence complex, messages.size=${action.messages.size}" }
372417
action.messages
373418
.filterIsInstance<IadvizeConnectorMessage>()
374419
.flatMap { it.replies }
375420
.map { it.sendByGraphQL(parameters, callback) }
376421
}
377422
}
423+
else -> {
424+
logger.debug { "sendProactiveMessage(): unhandled action type: ${action::class.simpleName}" }
425+
}
378426
}
379427
}
380428

381429
override fun endProactiveConversation(
382430
callback: ConnectorCallback,
383431
parameters: Map<String, String>,
384432
) {
433+
logger.debug { "endProactiveConversation(): BEFORE proactiveEnabled=$proactiveAnswerEnabled, thread=${Thread.currentThread().name}" }
434+
385435
flushProactiveConversation(callback, parameters)
386-
// Turn off the proactive answer mode
387436
proactiveAnswerEnabled = false
437+
438+
logger.debug { "endProactiveConversation(): AFTER proactiveEnabled=$proactiveAnswerEnabled" }
388439
}
389440

390441
/**
@@ -409,60 +460,82 @@ class IadvizeConnector internal constructor(
409460
}
410461
}
411462

412-
/**
413-
* Send [SendSentenceWithFootnotes] markdown using GraphQL
414-
* @param parameters the key value map of parameters
415-
*/
416463
private fun SendSentenceWithFootnotes.sendByGraphQL(parameters: Map<String, String>) {
417-
IadvizeGraphQLClient().sendProactiveActionOrMessage(
418-
parameters[IadvizeConnectorMetadata.CONVERSATION_ID.name]!!,
419-
parameters[IadvizeConnectorMetadata.CHAT_BOT_ID.name]?.toInt()!!,
420-
actionOrMessage =
421-
ChatbotActionOrMessageInput(
422-
chatbotMessage =
423-
ChatbotMessageInput(
424-
chatbotSimpleTextMessage = this.toMarkdown(),
464+
val conversationId = parameters[IadvizeConnectorMetadata.CONVERSATION_ID.name]
465+
val chatBotIdStr = parameters[IadvizeConnectorMetadata.CHAT_BOT_ID.name]
466+
val chatBotId = chatBotIdStr?.toIntOrNull()
467+
val messageText = this.toMarkdown()
468+
val caller = Thread.currentThread().stackTrace.getOrNull(2)?.methodName ?: "unknown"
469+
470+
logger.debug { "SendSentenceWithFootnotes.sendByGraphQL(): caller=$caller, conversationId=$conversationId, chatBotId=$chatBotId, messageLength=${messageText.length}" }
471+
472+
if (conversationId == null || chatBotId == null) {
473+
logger.debug { "SendSentenceWithFootnotes.sendByGraphQL(): ABORT - MISSING PARAMS conversationId=$conversationId, chatBotIdStr=$chatBotIdStr, chatBotId=$chatBotId" }
474+
return
475+
}
476+
477+
try {
478+
val startTime = System.currentTimeMillis()
479+
val result =
480+
IadvizeGraphQLClient().sendProactiveActionOrMessage(
481+
conversationId,
482+
chatBotId,
483+
actionOrMessage =
484+
ChatbotActionOrMessageInput(
485+
chatbotMessage = ChatbotMessageInput(chatbotSimpleTextMessage = messageText),
425486
),
426-
),
427-
)
487+
)
488+
val duration = System.currentTimeMillis() - startTime
489+
logger.debug { "SendSentenceWithFootnotes.sendByGraphQL(): result=$result, duration=${duration}ms" }
490+
} catch (e: Exception) {
491+
logger.debug(e) { "SendSentenceWithFootnotes.sendByGraphQL(): EXCEPTION ${e.message}" }
492+
}
428493
}
429494

430-
/**
431-
* Send [IadvizeReply] using GraphQL
432-
* @param parameters the key value map of parameters
433-
* @param callback the [IadvizeConnectorCallback]
434-
*/
435495
private fun IadvizeReply.sendByGraphQL(
436496
parameters: Map<String, String>,
437497
callback: IadvizeConnectorCallback,
438498
) {
499+
val conversationId = parameters[IadvizeConnectorMetadata.CONVERSATION_ID.name]
500+
val chatBotIdStr = parameters[IadvizeConnectorMetadata.CHAT_BOT_ID.name]
501+
val chatBotId = chatBotIdStr?.toIntOrNull()
502+
val caller = Thread.currentThread().stackTrace.getOrNull(2)?.methodName ?: "unknown"
503+
504+
logger.debug { "IadvizeReply.sendByGraphQL(): caller=$caller, replyType=${this::class.simpleName}, conversationId=$conversationId, chatBotId=$chatBotId" }
505+
506+
if (conversationId == null || chatBotId == null) {
507+
logger.debug { "IadvizeReply.sendByGraphQL(): ABORT - MISSING PARAMS conversationId=$conversationId, chatBotIdStr=$chatBotIdStr, chatBotId=$chatBotId" }
508+
return
509+
}
510+
439511
val actionOrMessage =
440512
when (this) {
441513
is IadvizeTransfer -> {
442-
// Check if a rule is available for distribution
443514
val response = callback.addDistributionRulesOnTransfer(this)
444515
if (response is IadvizeTransfer) {
445516
response.toChatBotActionOrMessageInput()
446517
} else {
447-
// If the distribution rule is not available, send the configured message when
448518
ChatbotActionOrMessageInput(
449-
chatbotMessage =
450-
ChatbotMessageInput(
451-
chatbotSimpleTextMessage = distributionRuleUnavailableMessage,
452-
),
519+
chatbotMessage = ChatbotMessageInput(chatbotSimpleTextMessage = distributionRuleUnavailableMessage),
453520
)
454521
}
455522
}
456-
457523
else -> this.toChatBotActionOrMessageInput()
458524
}
459525

460-
// Send a proactive action or message
461-
IadvizeGraphQLClient().sendProactiveActionOrMessage(
462-
parameters[IadvizeConnectorMetadata.CONVERSATION_ID.name]!!,
463-
parameters[IadvizeConnectorMetadata.CHAT_BOT_ID.name]?.toInt()!!,
464-
actionOrMessage = actionOrMessage,
465-
)
526+
try {
527+
val startTime = System.currentTimeMillis()
528+
val result =
529+
IadvizeGraphQLClient().sendProactiveActionOrMessage(
530+
conversationId,
531+
chatBotId,
532+
actionOrMessage = actionOrMessage,
533+
)
534+
val duration = System.currentTimeMillis() - startTime
535+
logger.debug { "IadvizeReply.sendByGraphQL(): result=$result, duration=${duration}ms" }
536+
} catch (e: Exception) {
537+
logger.debug(e) { "IadvizeReply.sendByGraphQL(): EXCEPTION ${e.message}" }
538+
}
466539
}
467540

468541
internal fun handleRequest(

‎bot/engine/src/main/kotlin/connector/ConnectorQueue.kt‎

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ import ai.tock.bot.engine.user.PlayerId
2222
import ai.tock.shared.Executor
2323
import com.google.common.cache.Cache
2424
import com.google.common.cache.CacheBuilder
25+
import mu.KotlinLogging
2526
import java.time.Duration
2627
import java.time.Instant
2728
import java.time.InstantSource
@@ -31,6 +32,8 @@ import java.util.concurrent.ConcurrentLinkedQueue
3132
import java.util.concurrent.TimeUnit
3233
import java.util.concurrent.atomic.AtomicBoolean
3334

35+
private val logger = KotlinLogging.logger {}
36+
3437
/**
3538
* A Queue to ensure the calls from the same user id are sent sequentially.
3639
*/
@@ -139,14 +142,17 @@ class ConnectorQueue(private val executor: Executor, private val clock: InstantS
139142
recipient: PlayerId,
140143
actionWrapper: ScheduledAction<T>,
141144
) {
145+
logger.debug { "add0(): recipientId=${recipient.id}, action=$actionWrapper, lastAnswer=${actionWrapper.lastInAnswer}, thread=${Thread.currentThread().name}" }
142146
val queue =
143147
messagesByRecipientMap
144148
.get(recipient.id) { UserQueue() }
145149
.apply {
146150
if (enqueueMessage(actionWrapper)) {
151+
logger.debug { "add0(): recipientId=${recipient.id}, QUEUED (waiting for previous), queueSize=$size" }
147152
return
148153
}
149154
}
155+
logger.debug { "add0(): recipientId=${recipient.id}, sending immediately" }
150156
sendNextAction(actionWrapper, queue)
151157
}
152158

@@ -159,11 +165,16 @@ class ConnectorQueue(private val executor: Executor, private val clock: InstantS
159165
Duration.between(clock.instant(), action.scheduledFor),
160166
if (queue.answerInProgress.get()) BotDefinition.minBreath else Duration.ZERO,
161167
)
168+
logger.debug { "sendNextAction(): action=$action, timeToWait=${timeToWait.toMillis()}ms, answerInProgress=${queue.answerInProgress.get()}, thread=${Thread.currentThread().name}" }
162169
executor.executeBlocking(timeToWait) {
163170
try {
171+
logger.debug { "sendNextAction(): EXECUTING action=$action, thread=${Thread.currentThread().name}" }
164172
action.joinAndSend()
173+
logger.debug { "sendNextAction(): COMPLETED action=$action" }
165174
} finally {
166-
queue.dequeueMessage()?.also { a ->
175+
val next = queue.dequeueMessage()
176+
logger.debug { "sendNextAction(): DEQUEUED, next=$next, remainingQueueSize=${queue.size}" }
177+
next?.also { a ->
167178
sendNextAction(a, queue)
168179
}
169180
}

‎bot/engine/src/main/kotlin/engine/TockBotBus.kt‎

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -287,30 +287,44 @@ internal class TockBotBus(
287287
timeout: Duration = Duration.ofSeconds(cleanupTimeoutProperty),
288288
): () -> Unit {
289289
val closed = AtomicBoolean(false)
290+
logger.debug { "deferMessageSending(): userId=${userId.id}, timeout=${timeout.seconds}s, thread=${Thread.currentThread().name}" }
290291
customActionSender.set { action, delay ->
291292
// we queue in the current thread to preserve message ordering
293+
logger.debug {
294+
"deferMessageSending.customActionSender(): userId=${userId.id}, actionType=${action::class.simpleName}, lastAnswer=${action.metadata.lastAnswer}, thread=${Thread.currentThread().name}"
295+
}
292296
scope.launch(start = CoroutineStart.UNDISPATCHED) {
293297
messageChannel.send(QueuedAction(action, delay))
298+
logger.debug { "deferMessageSending.customActionSender(): userId=${userId.id}, SENT to channel, lastAnswer=${action.metadata.lastAnswer}" }
294299
// the following code may happen in a different thread if the channel's buffer was full
295300
if (action.metadata.lastAnswer) {
301+
logger.debug { "deferMessageSending.customActionSender(): userId=${userId.id}, lastAnswer=true, CLOSING channel" }
296302
closed.store(true)
297303
messageChannel.close()
298304
}
299305
}
300306
}
301307
scope.launch(injector.provide<Executor>().asCoroutineDispatcher()) {
308+
logger.debug { "deferMessageSending.consumer(): userId=${userId.id}, STARTED, thread=${Thread.currentThread().name}" }
302309
for ((action, delay) in messageChannel) {
310+
logger.debug { "deferMessageSending.consumer(): userId=${userId.id}, RECEIVED from channel, actionType=${action::class.simpleName}, calling doSend()" }
303311
doSend(action, delay)
312+
logger.debug { "deferMessageSending.consumer(): userId=${userId.id}, doSend() COMPLETED" }
304313
}
314+
logger.debug { "deferMessageSending.consumer(): userId=${userId.id}, channel CLOSED, consumer EXITING" }
305315
}
306316
return {
307317
if (!closed.load()) {
318+
logger.debug { "deferMessageSending.cleanup(): userId=${userId.id}, scheduling force-close in ${timeout.seconds}s" }
308319
injector.provide<Executor>().executeBlocking(timeout) {
309320
if (!closed.load()) {
310321
logger.info("force-closing message channel")
322+
logger.debug { "deferMessageSending.cleanup(): userId=${userId.id}, FORCE-CLOSING (lastAnswer never received)" }
311323
messageChannel.close()
312324
}
313325
}
326+
} else {
327+
logger.debug { "deferMessageSending.cleanup(): userId=${userId.id}, channel already closed (lastAnswer received)" }
314328
}
315329
}
316330
}

0 commit comments

Comments
 (0)