* VRFS-2629 - one can follow the progression of a jam track being signed with detail

db/manifest

@@ -240,3 +240,4 @@ jam_track_tap_in.sql
 jam_track_available.sql
 active_jam_track.sql
 bpms_on_tap_in.sql
+jamtracks_job.sql

db/up/jamtracks_job.sql

@@ -0,0 +1,8 @@
+-- tracks state of resque job for jamtrack
+ALTER TABLE jam_track_rights ADD COLUMN signing_queued_at  TIMESTAMP WITHOUT TIME ZONE;
+ALTER TABLE jam_track_rights ADD COLUMN signing_started_at  TIMESTAMP WITHOUT TIME ZONE;
+ALTER TABLE jam_track_rights ADD COLUMN error_count INTEGER NOT NULL DEFAULT 0;
+ALTER TABLE jam_track_rights ADD COLUMN error_reason VARCHAR;
+ALTER TABLE jam_track_rights ADD COLUMN error_detail VARCHAR;
+ALTER TABLE jam_track_rights ADD COLUMN should_retry BOOLEAN NOT NULL DEFAULT FALSE;
+

pb/src/client_container.proto

@@ -80,6 +80,7 @@ message ClientMessage {
 
         // jamtracks notifications
         JAM_TRACK_SIGN_COMPLETE             = 260;
+        JAM_TRACK_SIGN_FAILED               = 261;
 
         TEST_SESSION_MESSAGE                = 295;
 
@@ -184,7 +185,9 @@ message ClientMessage {
     optional SourceDown                 source_down = 253;
 
     // jamtracks notification
-    optional JamTrackSignComplete jam_track_sign_complete=260;
+    optional JamTrackSignComplete       jam_track_sign_complete = 260;
+    optional JamTrackSignFailed         jam_track_sign_failed = 261;
+
 
     // Client-Session messages (to/from)  
     optional TestSessionMessage     test_session_message = 295;
@@ -605,6 +608,10 @@ message JamTrackSignComplete {
     required int32 jam_track_right_id = 1; // jam track right id
 }
 
+message JamTrackSignFailed {
+    required int32 jam_track_right_id = 1; // jam track right id
+}
+
 message SubscriptionMessage {
    optional string type = 1; // the type of the subscription
    optional string id = 2; // data about what to subscribe to, specifically

ruby/lib/jam_ruby/lib/subscription_message.rb

@@ -20,6 +20,10 @@ module JamRuby
     def self.mount_source_down_requested(mount)
       Notification.send_subscription_message('mount', mount.id, {change_type: IcecastSourceChange::CHANGE_TYPE_MOUNT_DOWN_REQUEST}.to_json )
     end
+
+    def self.jam_track_signing_job_change(jam_track_right)
+      Notification.send_subscription_message('jam_track_right', jam_track_right.id.to_s, {signing_state: jam_track_right.signing_state}.to_json )
+    end
   end
 end
 

ruby/lib/jam_ruby/message_factory.rb

@@ -724,6 +724,18 @@ module JamRuby
       )
     end
 
+    def jam_track_sign_failed(receiver_id, jam_track_right_id)
+      signed = Jampb::JamTrackSignFailed.new(
+          :jam_track_right_id => jam_track_right_id
+      )
+
+      Jampb::ClientMessage.new(
+          :type => ClientMessage::Type::JAM_TRACK_SIGN_FAILED,
+          :route_to => USER_TARGET_PREFIX + receiver_id, #:route_to => CLIENT_TARGET,
+          :jam_track_sign_failed=> signed
+      )
+    end
+
 
     def recording_master_mix_complete(receiver_id, recording_id, claimed_recording_id, band_id, msg, notification_id, created_at)
       recording_master_mix_complete = Jampb::RecordingMasterMixComplete.new(

ruby/lib/jam_ruby/models/jam_track_right.rb

@@ -10,6 +10,7 @@ module JamRuby
     validates :user, presence:true
     validates :jam_track, presence:true
     validate :verify_download_count
+    after_save :after_save
 
     validates_uniqueness_of     :user_id, scope: :jam_track_id
     
@@ -19,6 +20,15 @@ module JamRuby
 
     MAX_JAM_TRACK_DOWNLOADS = 1000
 
+    def after_save
+      # try to catch major transitions:
+
+      # if just queue time changes, start time changes, or signed time changes, send out a notice
+      if signing_queued_at_was != signing_queued_at || signing_started_at_was != signing_started_at || last_signed_at_was != last_signed_at
+        SubscriptionMessage.jam_track_signing_job_change(self)
+      end
+    end
+
     def store_dir
       "#{jam_track.store_dir}/rights"
     end
@@ -38,16 +48,33 @@ module JamRuby
       JamTrackRight.where("downloaded_since_sign=? AND updated_at <= ?", true, 5.minutes.ago).limit(1000)      
     end
 
+    def finish_errored(error_reason, error_detail)
+      self.last_signed_at = Time.now
+      self.error_count = self.error_count + 1
+      self.error_reason = error_reason
+      self.error_detail = error_detail
+      self.should_retry = self.error_count < 5
+      if save
+        Notification.send_jam_track_sign_failed(self)
+      else
+        raise "Error sending notification #{self.errors}"
+      end
+
+    end
     def finish_sign(length, md5)
       self.last_signed_at = Time.now
       self.length = length
       self.md5 = md5
       self.signed = true
+      self.error_count = 0
+      self.error_reason = nil
+      self.error_detail = nil
+      self.should_retry = false
       if save
         Notification.send_jam_track_sign_complete(self)
       else
         raise "Error sending notification #{self.errors}"
-      end      
+      end
     end
 
     # creates a short-lived URL that has access to the object.
@@ -64,18 +91,57 @@ module JamRuby
 
     def enqueue
       begin
+        JamTrackRight.where(:id => self.id).update_all(:signing_queued_at => Time.now, :signing_started_at => nil, :last_signed_at => nil)
         Resque.enqueue(JamTracksBuilder, self.id)
+        true
       rescue Exception => e
         # implies redis is down. we don't update started_at by bailing out here
         false
       end
-
-      # avoid db validations
-      JamTrackRight.where(:id => self.id).update_all(:last_downloaded_at => Time.now)
-
-      true
     end
 
+    # if the job is already signed, just queued up for signing, or currently signing, then don't enqueue... otherwise fire it off
+    def enqueue_if_needed
+      state = signing_state
+
+      if state == 'SIGNED' || state == 'SIGNING' || state == 'QUEUED'
+        false
+      else
+        enqueue
+        true
+      end
+    end
+    # returns easy to digest state field
+    # SIGNED - the package is ready to be downloaded
+    # ERROR - the package was built unsuccessfully
+    # SIGNING_TIMEOUT - the package was kicked off to be signed, but it seems to have hung
+    # SIGNING - the package is currently signing
+    # QUEUED_TIMEOUT - the package signing job (JamTrackBuilder) was queued, but never executed
+    # QUEUED - the package is queued to sign
+    # QUIET - the jam_track_right exists, but no job has been kicked off; a job needs to be enqueued
+    def signing_state
+      state = nil
+      if signed
+        state = 'SIGNED'
+      elsif error_count > 0
+        state = 'ERROR'
+      elsif signing_started_at
+        if Time.now - signing_started_at > APP_CONFIG.signing_job_run_max_time
+          state = 'SIGNING_TIMEOUT'
+        else
+          state = 'SIGNING'
+        end
+      elsif signing_queued_at
+        if Time.now - signing_queued_at > APP_CONFIG.signing_job_queue_max_time
+          state = 'QUEUED_TIMEOUT'
+        else
+          state = 'QUEUED'
+        end
+      else
+        state = 'QUIET' # needs to be poked to go build
+      end
+      state
+    end
     def update_download_count(count=1)
       self.download_count = self.download_count + count
       self.last_downloaded_at = Time.now

ruby/lib/jam_ruby/models/notification.rb

@@ -1190,6 +1190,19 @@ module JamRuby
         end
       end
 
+      def send_jam_track_sign_failed(jam_track_right)
+
+        notification = Notification.new
+        notification.jam_track_right_id = jam_track_right.id
+        notification.description = NotificationTypes::JAM_TRACK_SIGN_FAILED
+        notification.target_user_id = jam_track_right.user_id
+        notification.save!
+
+        msg = @@message_factory.jam_track_sign_failed(jam_track_right.user_id, jam_track_right.id)
+        @@mq_router.publish_to_user(jam_track_right.user_id, msg)
+        #@@mq_router.publish_to_all_clients(msg)
+      end
+
       def send_jam_track_sign_complete(jam_track_right)
 
         notification = Notification.new

ruby/lib/jam_ruby/resque/audiomixer.rb

@@ -240,7 +240,7 @@ module JamRuby
           @error_reason = "unhandled-job-exception"
           @error_detail = e.to_s
         end
-        mix.errored(error_reason, error_detail)
+        mix.errored(@error_reason, @error_detail)
 
       rescue Exception => e
         @@log.error "unable to post back to the database the error #{e}"

ruby/lib/jam_ruby/resque/jam_tracks_builder.rb

@@ -15,7 +15,7 @@ module JamRuby
     end
 
     attr_accessor :jam_track_right_id
-    
+
     def self.perform(jam_track_right_id)
       jam_track_builder = JamTracksBuilder.new()
       jam_track_builder.jam_track_right_id = jam_track_right_id
@@ -23,16 +23,53 @@ module JamRuby
     end
 
     def run
-      log.info("jam_track_builder job starting. jam_track_right_id #{jam_track_right_id}")
+      begin
-      @jam_track_right = JamTrackRight.find(jam_track_right_id)
+        log.info("jam_track_builder job starting. jam_track_right_id #{jam_track_right_id}")
-      JamRuby::JamTracksManager.save_jam_track_right_jkz(@jam_track_right)
 
-      length = @jam_track_right.url.size()
+        begin
-      md5 = Digest::MD5.new
+          @jam_track_right = JamTrackRight.find(jam_track_right_id)
 
-      @jam_track_right.finish_sign(length, md5.to_s)
+          # bailout check
+          if @jam_track_right.signed
+            log.debug("package is already signed. bailing")
+            return
+          end
 
-      log.info "Signed jamtrack to #{@jam_track_right[:url]}"
+          # track that it's started ( and avoid db validations )
-    end    
+          JamTrackRight.where(:id => @jam_track_right.id).update_all(:signing_started_at => Time.now, :should_retry => false)
+
+          JamRuby::JamTracksManager.save_jam_track_right_jkz(@jam_track_right)
+
+          length = @jam_track_right.url.size()
+          md5 = Digest::MD5.new
+
+          @jam_track_right.finish_sign(length, md5.to_s)
+
+          log.info "Signed jamtrack to #{@jam_track_right[:url]}"
+
+        rescue Exception => e
+          # record the error in the database
+          post_error(e)
+          # and let the job fail, alerting ops too
+          raise
+        end
+      end
+    end
+
+    # set @error_reason before you raise an exception, and it will be sent back as the error reason
+    # otherwise, the error_reason will be unhandled-job-exception
+    def post_error(e)
+      begin
+        # if error_reason is null, assume this is an unhandled error
+        unless @error_reason
+          @error_reason = "unhandled-job-exception"
+          @error_detail = e.to_s
+        end
+        @jam_track_right.finish_errored(@error_reason, @error_detail)
+
+      rescue Exception => e
+        log.error "unable to post back to the database the error #{e}"
+      end
+    end
   end
-end
+end

ruby/spec/jam_ruby/models/jam_track_right_spec.rb

@@ -124,5 +124,42 @@ describe JamTrackRight do
     end
   end
 
+  describe "signing_state" do
+    it "quiet" do
+      right = FactoryGirl.create(:jam_track_right)
+      right.signing_state.should eq('QUIET')
+    end
+
+    it "signed" do
+      right = FactoryGirl.create(:jam_track_right, signed: true)
+      right.signing_state.should eq('SIGNED')
+    end
+
+    it "error" do
+      right = FactoryGirl.create(:jam_track_right, error_count: 1)
+      right.signing_state.should eq('ERROR')
+    end
+
+    it "signing" do
+      right = FactoryGirl.create(:jam_track_right, signing_started_at: Time.now)
+      right.signing_state.should eq('SIGNING')
+    end
+
+    it "signing timeout" do
+      right = FactoryGirl.create(:jam_track_right, signing_started_at: Time.now - (APP_CONFIG.signing_job_run_max_time + 1))
+      right.signing_state.should eq('SIGNING_TIMEOUT')
+    end
+
+    it "queued" do
+      right = FactoryGirl.create(:jam_track_right, signing_queued_at: Time.now)
+      right.signing_state.should eq('QUEUED')
+    end
+
+    it "signing timeout" do
+      right = FactoryGirl.create(:jam_track_right, signing_queued_at: Time.now - (APP_CONFIG.signing_job_queue_max_time + 1))
+      right.signing_state.should eq('QUEUED_TIMEOUT')
+    end
+  end
+
 end
 

ruby/spec/support/utilities.rb

@@ -154,6 +154,14 @@ def app_config
       false
     end
 
+    def signing_job_run_max_time
+      60 # 1 minute
+    end
+
+    def signing_job_queue_max_time
+      20 # 20 seconds
+    end
+
     private
 
     def audiomixer_workspace_path

web/app/controllers/api_icecast_controller.rb

@@ -107,7 +107,6 @@ class ApiIcecastController < ApiController
   def show
     @mount = IcecastMount.find(params[:id])
 
-    puts "@MOUNT #{@mount}"
     respond_with @mount, responder: ApiResponder
   end
 

web/app/controllers/api_jam_tracks_controller.rb

@@ -2,7 +2,7 @@ class ApiJamTracksController < ApiController
 
   # have to be signed in currently to see this screen
   before_filter :api_signed_in_user
-  before_filter :lookup_jam_track_right, :only => :download
+  before_filter :lookup_jam_track_right, :only => [:download,:enqueue, :show_jam_track_right]
   
   respond_to :json
 
@@ -23,12 +23,13 @@ class ApiJamTracksController < ApiController
 
   def download  
     if @jam_track_right.valid?      
-      if (@jam_track_right && @jam_track_right.signed && @jam_track_right.url.present? &&@jam_track_right.url.file.exists?)        
+      if (@jam_track_right && @jam_track_right.signed && @jam_track_right.url.present? &&@jam_track_right.url.file.exists?)
+        JamTrackRight.where(:id => self.id).update_all(:last_downloaded_at => Time.now)
         @jam_track_right.update_download_count      
         @jam_track_right.save!
         redirect_to @jam_track_right.sign_url
       else
-        @jam_track_right.enqueue
+        @jam_track_right.enqueue_if_needed
         render :json => { :message => "not available, digitally signing Jam Track offline." }, :status => 202
       end
     else
@@ -36,6 +37,16 @@ class ApiJamTracksController < ApiController
     end        
   end
 
+  def enqueue
+    @jam_track_right.enqueue_if_needed
+
+    render :json => { :message => "enqueued" }, :status => 200
+  end
+
+  def show_jam_track_right
+
+  end
+
   def keys
     jamtrack_ids = params[:jamtracks]
 

web/app/views/api_jam_tracks/show_jam_track_right.rabl

@@ -0,0 +1,3 @@
+object @jam_track_right
+
+attributes :id, :signing_state, :error_count, :error_reason, :error_detail

web/config/application.rb

@@ -209,6 +209,10 @@ if defined?(Bundler)
 
     # Location of jamtracks python tool:
     config.jamtracks_dir = ENV['JAMTRACKS_DIR'] || File.expand_path(File.join(File.dirname(__FILE__), "..", "..", "..", "jamtracks"))
+    # amount of time before we think packaging job is broken
+    config.signing_job_run_max_time = 60 # 1 minute
+    # amount of time before we think the queue is stuck
+    config.signing_job_queue_max_time = 20 # 20 seconds
 
     config.email_alerts_alias         = 'nobody@jamkazam.com' # should be used for 'oh no' server down/service down sorts of emails
     config.email_generic_from         = 'nobody@jamkazam.com'

web/config/routes.rb

@@ -195,6 +195,8 @@ SampleApp::Application.routes.draw do
     match '/jamtracks' => 'api_jam_tracks#index', :via => :get, :as => 'api_jam_tracks_list'
     match '/jamtracks/downloads' => 'api_jam_tracks#downloads', :via => :get, :as => 'api_jam_tracks_downloads'
     match '/jamtracks/download/:id' => 'api_jam_tracks#download', :via => :get, :as => 'api_jam_tracks_download'
+    match '/jamtracks/enqueue/:id' => 'api_jam_tracks#enqueue', :via => :post, :as => 'api_jam_tracks_enqueue'
+    match '/jamtracks/show/:id' => 'api_jam_tracks#show_jam_track_right', :via => :get, :as => 'api_jam_tracks_show_right'
     match '/jamtracks/keys' => 'api_jam_tracks#keys', :via => :post, :as => 'api_jam_tracks_keys'
 
     # Shopping carts

web/spec/controllers/api_jam_tracks_controller_spec.rb

@@ -188,4 +188,28 @@ describe ApiJamTracksController do
       json[0]['error'].should == 'not_purchased'
     end
   end
+
+  describe "enqueue" do
+    it "success" do
+      right = FactoryGirl.create(:jam_track_right, user: @user, signed: false)
+      right.signing_queued_at.should be_nil
+      post :enqueue, {:format => 'json', :id => right.jam_track.id}
+      response.should be_success
+
+      right.reload
+      right.signing_queued_at.should_not be_nil
+    end
+  end
+
+  describe "show_jam_track_right" do
+    it "success" do
+      right = FactoryGirl.create(:jam_track_right, user: @user)
+
+      get :show_jam_track_right, {:id => right.jam_track.id}
+      response.should be_success
+      json = JSON.parse(response.body)
+      json['signing_state'].should eq('QUIET')
+      json['error_count'].should eq(0)
+    end
+  end
 end

web/spec/support/app_config.rb

@@ -70,6 +70,14 @@ def web_config
     def max_red_full_score
       100
     end
+
+    def signing_job_run_max_time
+      60 # 1 minute
+    end
+
+    def signing_job_queue_max_time
+      20 # 20 seconds
+    end
   end
   klass.new
 end