Added more info level logging

bin/robot-sweeper

@@ -10,26 +10,28 @@ require 'optparse'
 require 'awesome_print'
 
 class RobotSweeperCLI
-  
+
   def monitor_stale(flags = {})
     %w{dor sdr}.each do |repo|
+      ROBOT_LOG.info("##### Querying stale jobs for #{repo}")
       stale = Dor::WorkflowService.get_stale_queued_workflows(repo, hours_ago: 24, limit: 1000)
       ap({:stale => stale}) if flags[:debug]
       stale.each do |h|
         h[:repo] = repo
         ap({:h => h}) if flags[:debug]
-        Dor::WorkflowService.update_workflow_status(h[:repo], h[:druid], h[:workflow], h[:step], 'waiting', expected: 'queued')      
+        ROBOT_LOG.info("Changing status from queued to waiting for: #{h[:repo]}, #{h[:druid]}, #{h[:workflow]}, #{h[:step]}")
+        Dor::WorkflowService.update_workflow_status(h[:repo], h[:druid], h[:workflow], h[:step], 'waiting', expected: 'queued')
       end
     end
   end
-  
+
   # XXX: sweep up failed job if the Workflow service thinks the object is :queued
   def sweep_job(job, flags = {})
     ap({:job => job}) if flags[:debug]
     status = Dor::WorkflowService.get_workflow_status(job[:repo], job[:druid], job[:workflow], job[:step])
     ap({:status => status}) if flags[:debug]
-    ROBOT_LOG.debug { "Job for #{job[:druid]} has status '#{status}' from #{job[:error_q]}" }
-    
+    ROBOT_LOG.info { "Job for #{job[:druid]} has status '#{status}' from #{job[:error_q]}" }
+
     if flags[:change_to_errored] and status == 'queued'
       opts =  { :error_txt => "queue=#{job[:error_q]} backtrace=#{job[:error_backtrace]}" }
       ROBOT_LOG.info("Updating error status for #{job[:druid]} #{job[:error_msg]} #{opts}")
@@ -58,7 +60,7 @@ class RobotSweeperCLI
     failed_key = flags[:failed_key] || 'failed'
     ap({:failed_key => failed_key, :flags => flags}) if flags[:debug]
     n = Resque.redis.llen(failed_key).to_i
-    ROBOT_LOG.debug { "Found #{n} items in '#{failed_key}'" }
+    ROBOT_LOG.info { "Found #{n} items in '#{failed_key}'" }
     return if n < 1
     n.times.each do |i| # assume no deletions from failed queue
       failed = Resque.list_range(failed_key, i, 1)
@@ -74,11 +76,11 @@ class RobotSweeperCLI
         :error_q => failed['queue'],
         :error_backtrace => failed['backtrace'].join("\n")
       }
-      
+
       sweep_job(job, flags)
     end
   end
-  
+
   def run(args)
     flags = {
       :verbose => false,
@@ -88,29 +90,29 @@ class RobotSweeperCLI
       :robot_log_level => ENV['ROBOT_LOG_LEVEL'] || 'info',
       :robot_log => ENV['ROBOT_LOG'] || '-'
     }
-    
+
     OptionParser.new do |opts|
       opts.banner = "Usage:\t#{File.basename(__FILE__)} [flags]"
       opts.on('--environment=ENV', "Use the given environment (default: #{flags[:robot_environment]})") do |v|
         flags[:robot_environment] = v
       end
       opts.on('--log-level=LEVEL', "Use the given log-level (default: #{flags[:robot_log_level]})") do |v|
         flags[:robot_log_level] = v
-      end      
+      end
       opts.on('--log=FILE', "Use the given log file (default: #{flags[:robot_log]})") do |v|
         flags[:robot_log] = v
-      end      
+      end
       opts.on('-R SECONDS', '--repeat-every=SECONDS', "Keep running every SECONDS in an infinite loop") do |v|
         flags[:loop] = v.to_i
-      end      
+      end
       opts.on('-v', '--verbose', 'Run verbosely, use multiple times for debug level output') do
         flags[:debug] = true if flags[:verbose]  # -vv
         flags[:verbose] = true
       end
     end.parse!(args)
     ap({:args => args}) if flags[:debug]
     ap({:flags => flags}) if flags[:debug]
-    
+
     # boot up
     ENV['ROBOT_ENVIRONMENT'] = flags[:robot_environment]
     ENV['ROBOT_LOG_LEVEL'] = flags[:robot_log_level]
@@ -127,9 +129,9 @@ class RobotSweeperCLI
     rescue => e
       raise ArgumentError, "Missing boot file: #{e.message}"
     end
-    
+
     # Perform actual work finally
-    ROBOT_LOG.info("Starting RobotSweeper v#{RobotMaster::VERSION}: " + 
+    ROBOT_LOG.info("Starting RobotSweeper v#{RobotMaster::VERSION}: " +
                    "#{Resque.redis_id} v#{Redis.current.info['redis_version']}")
     start = Time.now
     while true do
@@ -140,7 +142,7 @@ class RobotSweeperCLI
         ROBOT_LOG.error("#{e}")
         raise e unless flags[:loop] > 0 # don't error out if looping
       end
-      
+
       # sleep for a while if we're looping, otherwise quit
       if flags[:loop] > 0
         ROBOT_LOG.debug { "Waiting #{flags[:loop]} seconds before next run" }
@@ -149,7 +151,7 @@ class RobotSweeperCLI
         break # iterate once
       end
     end
-    
+
     ROBOT_LOG.info("Finished RobotSweeper: #{(Time.now - start).to_i} seconds")
   end
 end