From 7d479847f544fa4bfcb2604025e5f730d59d51c2 Mon Sep 17 00:00:00 2001
From: Sam Vevang <sam.vevang@gmail.com>
Date: Wed, 9 Oct 2024 13:28:55 -0500
Subject: [PATCH] Vary log level output by error count

---
 app/jobs/publish_feed_job.rb                  | 14 +++--
 app/models/apple/asset_state_timeout_error.rb | 11 ++++
 test/jobs/publish_feed_job_test.rb            | 53 +++++++++++++------
 3 files changed, 58 insertions(+), 20 deletions(-)

diff --git a/app/jobs/publish_feed_job.rb b/app/jobs/publish_feed_job.rb
index fe3f05879..20fe83b5d 100644
--- a/app/jobs/publish_feed_job.rb
+++ b/app/jobs/publish_feed_job.rb
@@ -46,10 +46,18 @@ def publish_rss(podcast, feed)
     handle_rss_error(podcast, feed, e)
   end
 
-  def handle_apple_timeout_error(podcast, error, raise_error: true)
+  def handle_apple_timeout_error(podcast, asset_timeout_error)
     PublishingPipelineState.retry!(podcast)
-    Rails.logger.error("Asset processing timeout", {podcast_id: podcast.id, error: e.message, backtrace: e.backtrace.join("\n")})
-    # TODO Does not re-raise the error
+    Rails.logger.send(asset_timeout_error.log_level) do
+      [
+        "Asset processing timeout",
+        {
+          podcast_id: podcast.id,
+          error: asset_timeout_error.message,
+          backtrace: asset_timeout_error&.backtrace&.join("\n")
+        }
+      ]
+    end
   end
 
   def handle_apple_error(podcast, error)
diff --git a/app/models/apple/asset_state_timeout_error.rb b/app/models/apple/asset_state_timeout_error.rb
index 82e0b19b7..1b62134ba 100644
--- a/app/models/apple/asset_state_timeout_error.rb
+++ b/app/models/apple/asset_state_timeout_error.rb
@@ -12,5 +12,16 @@ def initialize(episodes)
     def episode_ids
       episodes.map(&:feeder_id)
     end
+
+    def log_level
+      case attempts
+      when 0..4
+        :warn
+      when 5
+        :error
+      else
+        :fatal
+      end
+    end
   end
 end
diff --git a/test/jobs/publish_feed_job_test.rb b/test/jobs/publish_feed_job_test.rb
index 6264c3c05..11df4cc68 100644
--- a/test/jobs/publish_feed_job_test.rb
+++ b/test/jobs/publish_feed_job_test.rb
@@ -105,12 +105,16 @@
   end
 
   describe "publishing to apple" do
+    let(:podcast) { create(:podcast) }
+    let(:public_feed) { podcast.default_feed }
+    let(:private_feed) { create(:apple_feed, podcast: podcast) }
     let(:apple_feed) { private_feed }
-    let(:apple_config) { podcast.apple_config }
+    let(:apple_config) { private_feed.apple_config }
+    let(:apple_publisher) { apple_config.build_publisher }
 
     before do
       assert private_feed.persisted?
-      assert podcast.reload.apple_config.present?
+      assert apple_config.persisted?
     end
 
     describe "#perform" do
@@ -163,25 +167,40 @@
           PublishingQueueItem.create!(podcast: feed.podcast)
         end
 
-        it "raises an error if the apple publishing fails" do
-          assert apple_feed.apple_config.present?
-          assert apple_feed.apple_config.publish_enabled
-
-          PublishAppleJob.stub(:do_perform, ->(*, **) { raise "some apple error" }) do
-            assert_raises(RuntimeError) { PublishingPipelineState.attempt!(feed.podcast, perform_later: false) }
+        let(:episode1) { build(:uploaded_apple_episode, show: apple_publisher.show) }
+        let(:episode2) { build(:uploaded_apple_episode, show: apple_publisher.show) }
+        let(:episodes) { [episode1, episode2] }
 
-            assert_equal ["created", "started", "error", "error_apple"].sort, PublishingPipelineState.where(podcast: feed.podcast).latest_pipelines.pluck(:status).sort
-          end
-        end
-
-        it "raises an error if the apple publishing times out" do
+        it "logs message if the apple publishing times out" do
           assert apple_feed.apple_config.present?
           assert apple_feed.apple_config.publish_enabled
 
-          PublishAppleJob.stub(:do_perform, ->(*, **) { raise Apple::AssetStateTimeoutError.new([]) }) do
-            assert_raises(Apple::AssetStateTimeoutError) { PublishingPipelineState.attempt!(feed.podcast, perform_later: false) }
-
-            assert_equal ["created", "started", "error", "error_apple"].sort, PublishingPipelineState.where(podcast: feed.podcast).latest_pipelines.pluck(:status).sort
+          expected_level_for_timeouts = [
+            [0, 40],
+            [1, 40],
+            [2, 40],
+            [3, 40],
+            [4, 40],
+            [5, 50],
+            [6, 60]
+          ]
+
+          expected_level_for_timeouts.each do |(attempts, level)|
+            # simulate a episode waiting n times
+            episodes.first.apple_episode_delivery_status.update(asset_processing_attempts: attempts)
+
+            PublishAppleJob.stub(:do_perform, ->(*, **) { raise Apple::AssetStateTimeoutError.new(episodes) }) do
+              lines = capture_json_logs do
+                PublishingQueueItem.ensure_queued!(feed.podcast)
+                PublishingPipelineState.attempt!(feed.podcast, perform_later: false)
+              end
+
+              log = lines.find { |l| l["msg"].include?("Asset processing timeout") }
+              assert log.present?
+              assert_equal level, log["level"]
+
+              assert_equal ["created", "started", "retry", "error_apple"].sort, PublishingPipelineState.where(podcast: feed.podcast).latest_pipelines.pluck(:status).sort
+            end
           end
         end
       end