From 2c798e8860345ebe4613c68c0ac91a5babcb4ee7 Mon Sep 17 00:00:00 2001 From: Seth Call Date: Fri, 9 Jan 2015 11:23:20 -0600 Subject: [PATCH] * VRFS-2629 - one can follow the progression of a jam track being signed with detail --- db/manifest | 1 + db/up/jamtracks_job.sql | 8 ++ pb/src/client_container.proto | 9 ++- ruby/lib/jam_ruby/lib/subscription_message.rb | 4 + ruby/lib/jam_ruby/message_factory.rb | 12 +++ ruby/lib/jam_ruby/models/jam_track_right.rb | 78 +++++++++++++++++-- ruby/lib/jam_ruby/models/notification.rb | 13 ++++ ruby/lib/jam_ruby/resque/audiomixer.rb | 2 +- .../lib/jam_ruby/resque/jam_tracks_builder.rb | 57 +++++++++++--- .../jam_ruby/models/jam_track_right_spec.rb | 37 +++++++++ ruby/spec/support/utilities.rb | 8 ++ web/app/controllers/api_icecast_controller.rb | 1 - .../controllers/api_jam_tracks_controller.rb | 17 +++- .../api_jam_tracks/show_jam_track_right.rabl | 3 + web/config/application.rb | 4 + web/config/routes.rb | 2 + .../api_jam_tracks_controller_spec.rb | 24 ++++++ web/spec/support/app_config.rb | 8 ++ 18 files changed, 266 insertions(+), 22 deletions(-) create mode 100644 db/up/jamtracks_job.sql create mode 100644 web/app/views/api_jam_tracks/show_jam_track_right.rabl diff --git a/db/manifest b/db/manifest index 6abcd0c07..fb64e8498 100755 --- a/db/manifest +++ b/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 diff --git a/db/up/jamtracks_job.sql b/db/up/jamtracks_job.sql new file mode 100644 index 000000000..010012027 --- /dev/null +++ b/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; + diff --git a/pb/src/client_container.proto b/pb/src/client_container.proto index 252e9166b..5d5ecf100 100644 --- a/pb/src/client_container.proto +++ b/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 diff --git a/ruby/lib/jam_ruby/lib/subscription_message.rb b/ruby/lib/jam_ruby/lib/subscription_message.rb index 8f4320249..ec161ec8f 100644 --- a/ruby/lib/jam_ruby/lib/subscription_message.rb +++ b/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 diff --git a/ruby/lib/jam_ruby/message_factory.rb b/ruby/lib/jam_ruby/message_factory.rb index fab355772..e8cf40b1b 100644 --- a/ruby/lib/jam_ruby/message_factory.rb +++ b/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( diff --git a/ruby/lib/jam_ruby/models/jam_track_right.rb b/ruby/lib/jam_ruby/models/jam_track_right.rb index fbd97bc78..affee58a5 100644 --- a/ruby/lib/jam_ruby/models/jam_track_right.rb +++ b/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 diff --git a/ruby/lib/jam_ruby/models/notification.rb b/ruby/lib/jam_ruby/models/notification.rb index 783f39fd2..5fa628f3a 100644 --- a/ruby/lib/jam_ruby/models/notification.rb +++ b/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 diff --git a/ruby/lib/jam_ruby/resque/audiomixer.rb b/ruby/lib/jam_ruby/resque/audiomixer.rb index cbe62d92e..e0a3b065e 100644 --- a/ruby/lib/jam_ruby/resque/audiomixer.rb +++ b/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}" diff --git a/ruby/lib/jam_ruby/resque/jam_tracks_builder.rb b/ruby/lib/jam_ruby/resque/jam_tracks_builder.rb index cc782a5ec..19d836462 100644 --- a/ruby/lib/jam_ruby/resque/jam_tracks_builder.rb +++ b/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}") - @jam_track_right = JamTrackRight.find(jam_track_right_id) - JamRuby::JamTracksManager.save_jam_track_right_jkz(@jam_track_right) + begin + log.info("jam_track_builder job starting. jam_track_right_id #{jam_track_right_id}") - length = @jam_track_right.url.size() - md5 = Digest::MD5.new + begin + @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]}" - end + # track that it's started ( and avoid db validations ) + 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 \ No newline at end of file +end diff --git a/ruby/spec/jam_ruby/models/jam_track_right_spec.rb b/ruby/spec/jam_ruby/models/jam_track_right_spec.rb index 0632fa7b7..b92bfa04b 100644 --- a/ruby/spec/jam_ruby/models/jam_track_right_spec.rb +++ b/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 diff --git a/ruby/spec/support/utilities.rb b/ruby/spec/support/utilities.rb index d2dbb4056..fda7ec00a 100644 --- a/ruby/spec/support/utilities.rb +++ b/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 diff --git a/web/app/controllers/api_icecast_controller.rb b/web/app/controllers/api_icecast_controller.rb index 7edd4fee5..e48892f7e 100644 --- a/web/app/controllers/api_icecast_controller.rb +++ b/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 diff --git a/web/app/controllers/api_jam_tracks_controller.rb b/web/app/controllers/api_jam_tracks_controller.rb index 5ecb29774..31eb42699 100644 --- a/web/app/controllers/api_jam_tracks_controller.rb +++ b/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] diff --git a/web/app/views/api_jam_tracks/show_jam_track_right.rabl b/web/app/views/api_jam_tracks/show_jam_track_right.rabl new file mode 100644 index 000000000..e72c3f5b4 --- /dev/null +++ b/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 \ No newline at end of file diff --git a/web/config/application.rb b/web/config/application.rb index ae3f2a508..a396cb57f 100644 --- a/web/config/application.rb +++ b/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' diff --git a/web/config/routes.rb b/web/config/routes.rb index e0642c69d..87c5db2e3 100644 --- a/web/config/routes.rb +++ b/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 diff --git a/web/spec/controllers/api_jam_tracks_controller_spec.rb b/web/spec/controllers/api_jam_tracks_controller_spec.rb index ddb44ab32..87f473b03 100644 --- a/web/spec/controllers/api_jam_tracks_controller_spec.rb +++ b/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 diff --git a/web/spec/support/app_config.rb b/web/spec/support/app_config.rb index c1f4ae4ba..0a7c63cae 100644 --- a/web/spec/support/app_config.rb +++ b/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