Thread through new error interface

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

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

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

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

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
 

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