diff --git a/config/initializers/sidekiq.rb b/config/initializers/sidekiq.rb index 7b78b466a..a3800c5fc 100644 --- a/config/initializers/sidekiq.rb +++ b/config/initializers/sidekiq.rb @@ -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 diff --git a/enterprise/app/jobs/captain/conversation/response_builder_job.rb b/enterprise/app/jobs/captain/conversation/response_builder_job.rb index f37086816..45b6d9ad2 100644 --- a/enterprise/app/jobs/captain/conversation/response_builder_job.rb +++ b/enterprise/app/jobs/captain/conversation/response_builder_job.rb @@ -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? diff --git a/enterprise/app/services/captain/conversation/response_lifecycle_logging.rb b/enterprise/app/services/captain/conversation/response_lifecycle_logging.rb new file mode 100644 index 000000000..b0ef5fcfa --- /dev/null +++ b/enterprise/app/services/captain/conversation/response_lifecycle_logging.rb @@ -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 diff --git a/lib/captain_response_dequeued_logger.rb b/lib/captain_response_dequeued_logger.rb new file mode 100644 index 000000000..7c61e5642 --- /dev/null +++ b/lib/captain_response_dequeued_logger.rb @@ -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