test: Add focused Captain response lifecycle logs (#15364)

## What changed

This pull request adds three focused log emitters for Captain V2
response jobs:

* `job_dequeued` when Sidekiq fetches the job from Redis
* `job_skipped` when the conversation is not Pending at the first job
guard
* `response_discarded` when a newer customer message exists before model
generation

The dequeue middleware identifies V2 jobs by the triggering message ID
in the third serialized Active Job argument. It does not log Captain V1
or other Sidekiq jobs.

## Why

Recent production incidents have an enqueue record but no later job
record. Active Job `Performing` and `Performed` logs are now available
temporarily, but they do not show whether Sidekiq fetched a job before a
worker disappeared.

The dequeue log closes that gap. The two application logs explain the
early exits that otherwise produce no model trace.

The production root cause remains unresolved. This pull request adds
evidence for the next occurrence and does not change Captain response
behavior.

## Log volume

A Captain V2 response job adds one dequeue line. The other two lines
occur only on an early status skip or a pre-generation burst discard.
Existing Active Job, Langfuse, completion, failure, handoff, and usage
logs cover later stages.

## Validation

* Ruby syntax checks passed for the four implementation files.
* RuboCop found no offenses in the four implementation files.
* No new specs were added because this is temporary diagnostic logging
with no response behavior change.
This commit is contained in:
Aakash Bakhle
2026-08-09 09:01:03 +05:30
committed by GitHub
parent f12529105b
commit a4eae9710a
4 changed files with 59 additions and 11 deletions

View File

@@ -1,4 +1,5 @@
require Rails.root.join('lib/redis/config')
require Rails.root.join('lib/captain_response_dequeued_logger')
schedule_file = 'config/schedule.yml'
@@ -18,10 +19,10 @@ end
Sidekiq.configure_server do |config|
config.redis = Redis::Config.app
if ActiveModel::Type::Boolean.new.cast(ENV.fetch('ENABLE_SIDEKIQ_DEQUEUE_LOGGER', false))
config.server_middleware do |chain|
chain.add ChatwootDequeuedLogger
end
config.server_middleware do |chain|
chain.add CaptainResponseDequeuedLogger
chain.add ChatwootDequeuedLogger if ActiveModel::Type::Boolean.new.cast(ENV.fetch('ENABLE_SIDEKIQ_DEQUEUE_LOGGER', false))
end
# skip the default start stop logging

View File

@@ -3,6 +3,7 @@ class Captain::Conversation::ResponseBuilderJob < ApplicationJob
include Captain::Conversation::V1FalsePromiseHandler
include Captain::Conversation::V2LifecycleEvents
include Captain::Conversation::MessageBuilder
include Captain::Conversation::ResponseLifecycleLogging
MAX_MESSAGE_LENGTH = 10_000
retry_on ActiveStorage::FileNotFoundError, attempts: 3, wait: 2.seconds
@@ -14,12 +15,13 @@ class Captain::Conversation::ResponseBuilderJob < ApplicationJob
@assistant = assistant
@responding_to_message_id = responding_to_message_id if captain_v2_enabled?
return unless conversation_pending?
return log_non_pending unless conversation_pending?
Current.executed_by = @assistant
return generate_and_process_response unless captain_v2_enabled?
return if newer_customer_message_arrived?
return log_pre_generation_discard if newer_customer_message_arrived?
generate_response_with_v2
rescue ActiveStorage::FileNotFoundError, Faraday::BadRequestError => e
@@ -223,11 +225,6 @@ class Captain::Conversation::ResponseBuilderJob < ApplicationJob
)
end
def conversation_pending?
status = Conversation.uncached { Conversation.where(id: @conversation.id).pick(:status) }
status == 'pending' || status == Conversation.statuses[:pending]
end
def newer_customer_message_arrived?
return false if @responding_to_message_id.blank?

View File

@@ -0,0 +1,24 @@
module Captain::Conversation::ResponseLifecycleLogging
private
def conversation_pending?
@observed_conversation_status = Conversation.uncached { Conversation.where(id: @conversation.id).pick(:status) }
@observed_conversation_status == 'pending' || @observed_conversation_status == Conversation.statuses[:pending]
end
def log_non_pending
return if @responding_to_message_id.nil?
Rails.logger.info(
"[CAPTAIN][ResponseLifecycle] event=job_skipped reason=conversation_not_pending conversation_id=#{@conversation.id} " \
"responding_to_message_id=#{@responding_to_message_id} conversation_status=#{@observed_conversation_status}"
)
end
def log_pre_generation_discard
Rails.logger.info(
'[CAPTAIN][ResponseLifecycle] event=response_discarded reason=newer_customer_message_before_generation ' \
"conversation_id=#{@conversation.id} responding_to_message_id=#{@responding_to_message_id}"
)
end
end

View File

@@ -0,0 +1,26 @@
# Records the Sidekiq fetch boundary for Captain response jobs without logging every job.
class CaptainResponseDequeuedLogger
JOB_CLASS = 'Captain::Conversation::ResponseBuilderJob'.freeze
def call(_worker, job, queue)
log_dequeued(job, queue) if captain_v2_response_job?(job)
yield
end
private
def log_dequeued(job, queue)
active_job_id = job.dig('args', 0, 'job_id')
responding_to_message_id = job.dig('args', 0, 'arguments', 2)
Sidekiq.logger.info(
"[CAPTAIN][ResponseLifecycle] event=job_dequeued active_job_id=#{active_job_id} provider_job_id=#{job['jid']} " \
"responding_to_message_id=#{responding_to_message_id} queue=#{queue}"
)
end
def captain_v2_response_job?(job)
return false unless job['wrapped'] == JOB_CLASS
!job.dig('args', 0, 'arguments', 2).nil?
end
end