From 46592c9ce8d1155a4a091bf499c672e5534cc70b Mon Sep 17 00:00:00 2001 From: Sam Vevang Date: Wed, 9 Oct 2024 09:55:42 -0500 Subject: [PATCH] Thread through new error interface --- app/jobs/publish_feed_job.rb | 3 +++ app/models/apple/asset_state_timeout_error.rb | 15 +++++++++++ app/models/apple/publisher.rb | 8 +++--- test/models/apple/publisher_test.rb | 26 ++++++++++++------- test/models/publishing_pipeline_state_test.rb | 13 +++++++++- test/test_helper.rb | 13 ++++++++++ 6 files changed, 63 insertions(+), 15 deletions(-) create mode 100644 app/models/apple/asset_state_timeout_error.rb diff --git a/app/jobs/publish_feed_job.rb b/app/jobs/publish_feed_job.rb index 7ff0d44ad..2157b9d95 100644 --- a/app/jobs/publish_feed_job.rb +++ b/app/jobs/publish_feed_job.rb @@ -18,6 +18,9 @@ def perform(podcast, pub_item) podcast.feeds.each { |feed| publish_apple(podcast, feed) } podcast.feeds.each { |feed| publish_rss(podcast, feed) } PublishingPipelineState.complete!(podcast) + rescue Apple::AssetStateTimeoutError => e + PublishingPipelineState.error!(podcast) + Rails.logger.error("Asset processing timeout", {podcast_id: podcast.id, error: e.message, backtrace: e.backtrace.join("\n")}) rescue => e PublishingPipelineState.error!(podcast) # TODO, we can remove this once we have a better way to track errors diff --git a/app/models/apple/asset_state_timeout_error.rb b/app/models/apple/asset_state_timeout_error.rb new file mode 100644 index 000000000..da981c256 --- /dev/null +++ b/app/models/apple/asset_state_timeout_error.rb @@ -0,0 +1,15 @@ +module Apple + class AssetStateTimeoutError < RuntimeError + attr_reader :episodes, :attempts + + def initialize(episodes) + @episodes = episodes + @attempts = episodes.map { |ep| ep.apple_episode_delivery_status.asset_processing_attempts }.max + super("Timeout waiting for asset state change: Episodes: #{episode_ids} Attempts: #{attempts}") + end + + def episode_ids + episodes.map(&:feeder_id) + end + end +end diff --git a/app/models/apple/publisher.rb b/app/models/apple/publisher.rb index 4464d5819..a2c1fbd37 100644 --- a/app/models/apple/publisher.rb +++ b/app/models/apple/publisher.rb @@ -233,11 +233,11 @@ def wait_for_asset_state(eps) # Mark the episodes as waiting again for asset processing eps.each { |ep| ep.apple_episode_delivery_status.increment_asset_wait } - (waiting_timed_out, _) = Apple::Episode.wait_for_asset_state(api, eps) + (waiting_timed_out, remaining_eps) = Apple::Episode.wait_for_asset_state(api, eps) if waiting_timed_out - attempts = eps.map { |ep| ep.apple_episode_delivery_status.asset_processing_attempts }.max - Rails.logger.info("Timed out waiting for asset state", {attempts: attempts, episode_count: eps.length}) - raise "Timed out waiting for asset state" + e = Apple::AssetStateTimeoutError.new(remaining_eps) + Rails.logger.info("Timed out waiting for asset state", {attempts: e.attempts, episode_count: e.episodes.length}) + raise e end end end diff --git a/test/models/apple/publisher_test.rb b/test/models/apple/publisher_test.rb index 5c6c05246..55f7e8f3c 100644 --- a/test/models/apple/publisher_test.rb +++ b/test/models/apple/publisher_test.rb @@ -414,21 +414,27 @@ ) ) ] * 2 # Create two identical episode structures + eps = eps.map.with_index do |e, i| # Set the feeder_id to a unique value + e = e.dup + e.feeder_id = i + 1 + e + end - log_message = nil - Rails.logger.stub :tagged, nil do - Rails.logger.stub :info, ->(msg, data) { log_message = [msg, data] } do - Apple::Episode.stub :wait_for_asset_state, [true, nil] do - error = assert_raises(RuntimeError) do - publisher.wait_for_asset_state(eps) - end - assert_equal "Timed out waiting for asset state", error.message + assert publisher + logs = capture_json_logs do + Apple::Episode.stub :wait_for_asset_state, [true, eps] do + error = assert_raises(RuntimeError) do + publisher.wait_for_asset_state(eps) end + assert_equal "Timeout waiting for asset state change: Episodes: [1, 2] Attempts: 3", error.message end end - assert_equal "Timed out waiting for asset state", log_message[0] - assert_equal({attempts: 3, episode_count: 2}, log_message[1]) + log = logs[0] + assert_equal "Timed out waiting for asset state", log[:msg] + assert_equal 30, log[:level] + assert_equal 3, log[:attempts] + assert_equal 2, log[:episode_count] end it "should raise an error when wait times out" do diff --git a/test/models/publishing_pipeline_state_test.rb b/test/models/publishing_pipeline_state_test.rb index ea5e7c613..70db46bd8 100644 --- a/test/models/publishing_pipeline_state_test.rb +++ b/test/models/publishing_pipeline_state_test.rb @@ -251,13 +251,24 @@ describe "error!" do it 'sets the status to "error"' do + pqi = nil PublishFeedJob.stub_any_instance(:save_file, nil) do PublishFeedJob.stub_any_instance(:publish_apple, ->(*args) { raise "error" }) do - assert_raises(RuntimeError) { PublishingPipelineState.attempt!(podcast, perform_later: false) } + pqi = PublishingQueueItem.ensure_queued!(podcast) + PublishingPipelineState.attempt!(podcast, perform_later: false) end end assert_equal ["created", "started", "error"].sort, PublishingPipelineState.where(podcast: podcast).map(&:status).sort + assert_equal "error", pqi.reload.last_pipeline_state + + # it retries + PublishingPipelineState.retry_failed_pipelines! + assert_equal ["created", "started", "error", "created"].sort, PublishingPipelineState.where(podcast: podcast).map(&:status).sort + res_pqi = PublishingQueueItem.current_unfinished_item(podcast) + + assert res_pqi.id > pqi.id + assert_equal "created", res_pqi.last_pipeline_state end end diff --git a/test/test_helper.rb b/test/test_helper.rb index 0efc19100..5e27ee50f 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -49,6 +49,19 @@ class Minitest::Spec include FactoryBot::Syntax::Methods end +def capture_json_logs(&block) + old_logger = Rails.logger + log = StringIO.new + feeder_logger = FeederLogger.new(log) + feeder_logger.formatter = Ougai::Formatters::Bunyan.new + Rails.logger = ActiveSupport::TaggedLogging.new(feeder_logger) + block.call + log.rewind + log.read.split("\n").map { |line| JSON.parse(line).with_indifferent_access } +ensure + Rails.logger = old_logger +end + def json_file(name) test_file("/fixtures/#{name}.json") end