Added logging and better exception handling

lib/aebus.rb

@@ -5,6 +5,7 @@
 require_relative 'config/config'
 require_relative 'aebus/version'
 require_relative 'aebus/logging'
+require_relative 'aebus/volume_status'
 require_relative 'ec2/zones'
 require_relative 'ec2/snapshot'
 
@@ -18,73 +19,96 @@ class Core
     AEBUS_TAG = "Aebus"
 
     def status(args, options)
-      current_time_utc = Time.now.utc
+      @current_time_utc = Time.now.utc
       init_logger options
-      logger.info("status check started at #{current_time_utc}")
+      logger.info("status check started at #{@current_time_utc}")
 
-      config = Config::Config.new(File.join(File.dirname("."), options.config), current_time_utc)
-      @ec2 = AWS::EC2::Base.new(:access_key_id => config.defaults["access_key_id"],
-                               :secret_access_key => config.defaults["secret_access_key"],
-                               :server => EC2::zone_to_url(config.defaults["zone"]))
+      @config = Config::Config.new(File.join(File.dirname("."), options.config), @current_time_utc)
+      @ec2 = AWS::EC2::Base.new(:access_key_id => @config.defaults["access_key_id"],
+                                :secret_access_key => @config.defaults["secret_access_key"],
+                                :server => EC2::zone_to_url(@config.defaults["zone"]))
 
 
 
-      to_backup = 0
-      to_be_purged = 0
-      max_delay = 0
-      target_volumes = calculate_target_volumes(config, args)
+      target_volumes = target_volumes(args)
 
       abort("Configuration contains invalid volumes") unless validate_target_volumes(target_volumes)
 
-      snap_map = get_snapshots_map
+      status = check_status(target_volumes)
 
+      message = "status check completed - #{status[:total]} volume(s) checked,  #{status[:to_backup]} to be backed up, max delay detected #{status[:delay]}s, #{status[:to_purge]} snapshots to be purged"
+      logger.info message
+      puts message
+
+
+
+    end
+
+    def check_status(target_volumes)
+      result = {}
+      result[:timestamp] = @current_time_utc
+      snap_map = get_snapshots_map
+      result[:volumes] = Array.new
+      to_backup = 0
+      to_purge = 0
       target_volumes.each do |target|
-        volume = config.volumes[target]
-        to_be_run = volume.backups_to_be_run(snap_map[target], current_time_utc)
-        max_delay = [max_delay, to_be_run[0]].max
-        tags = to_be_run[1]
-        if (tags.count > 0) then
+        vs = VolumeStatus.new(target)
+        volume = @config.volumes[target]
+        vs.last_backup = volume.last_backup
+        vs.next_backup = volume.next_backup
+        to_be_run = volume.backups_to_be_run(snap_map[target], @current_time_utc)
+
+        vs.delay = to_be_run[0]
+        vs.tags = to_be_run[1]
+
+        if (vs.needs_backup?) then
+          logger.info("Volume #{target} needs to be backed up. Tags: #{vs.tags.join(',')}, max delay #{vs.delay}")
           to_backup += 1
-          logger.info("Volume #{target} needs to be backed up. Tags: #{tags.join(',')}, max delay #{to_be_run[0]}")
         else
           logger.info("Volume #{target} does not need to be backed up")
         end
 
-        purgeable_snapshots =volume.purgeable_snapshots(snap_map[target])
-        logger.info("Volume #{target} has #{purgeable_snapshots.count} purgeable snapshot(s): #{purgeable_snapshots.inject([]){|x, snap| x << snap.id}.join(',')}")
-        to_be_purged += purgeable_snapshots.count
-
+        vs.purgeable_snapshot_ids = volume.purgeable_snapshot_ids(snap_map[target])
+        to_purge += vs.purgeable_snapshot_ids.count  if vs.purgeable_snapshot_ids
+        logger.info("Volume #{target} has #{vs.purgeable_snapshot_ids.count} purgeable snapshot(s): #{vs.purgeable_snapshot_ids.join(',')}")
 
+        result[:volumes] << vs
 
       end
+      result[:to_backup] = to_backup
+      result[:to_purge] = to_purge
+      result[:delay] = result[:volumes].inject([0]) {|acc, vs| acc << vs.delay}.max
+      result[:total] = result[:volumes].count
+      result
 
-      message = "status check completed - #{to_backup} volume(s) to be backed up, max delay detected #{max_delay}s, #{to_be_purged} snapshots to be purged"
-      logger.info message
-      puts message
-
+    end
 
 
-    end
 
     def backup(args, options)
 
+
       backed_up = 0
-      current_time_utc = Time.now.utc
-      config = Config::Config.new(File.join(File.dirname("."), options.config), current_time_utc)
+      max_delay = 0
+      purged = 0
+      to_purge = 0
+      to_backup = 0
+      @current_time_utc = Time.now.utc
+      @config = Config::Config.new(File.join(File.dirname("."), options.config), @current_time_utc)
 
       init_logger options
-      logger.info("backup started at #{current_time_utc}")
+      logger.info("backup started at #{@current_time_utc}")
 
-      @ec2 = AWS::EC2::Base.new(:access_key_id => config.defaults["access_key_id"],
-                               :secret_access_key => config.defaults["secret_access_key"],
-                               :server => EC2::zone_to_url(config.defaults["zone"]))
+      @ec2 = AWS::EC2::Base.new(:access_key_id => @config.defaults["access_key_id"],
+                                :secret_access_key => @config.defaults["secret_access_key"],
+                                :server => EC2::zone_to_url(@config.defaults["zone"]))
 
-      target_volumes = calculate_target_volumes(config, args)
+      target_volumes = target_volumes(args)
       if (options.manual) then
 
         target_volumes.each do |volume|
-
-          backup_volume(volume, current_time_utc, [EC2::AEBUS_MANUAL_TAG])
+          to_backup += 1
+          break unless backup_volume(volume, [EC2::AEBUS_MANUAL_TAG])
           backed_up += 1
 
         end
@@ -93,18 +117,18 @@ def backup(args, options)
 
         snap_map = get_snapshots_map
 
-        purged = 0
-        max_delay = 0
+
         target_volumes.each do |target|
 
           volume = config.volumes[target]
-          to_be_run = volume.backups_to_be_run(snap_map[target], current_time_utc)
-          max_delay = max(max_delay, to_be_run[0])
+          to_be_run = volume.backups_to_be_run(snap_map[target], @current_time_utc)
+          max_delay = [max_delay, to_be_run[0]].max
           tags = to_be_run[1]
           if (tags.count > 0) then
             tags << EC2::AEBUS_AUTO_TAG
             logger.info("Creating backup for volume #{target} with tags #{tags.join(',')}, max delay #{max_delay}")
-            backup_volume(target, current_time_utc, tags)
+            to_backup +=1
+            break unless backup_volume(target, tags)
             backed_up += 1
           else
             logger.info("Volume #{target} does not need to be backed up")
@@ -116,10 +140,11 @@ def backup(args, options)
         if (options.purge) then
           target_volumes.each do |target|
             volume = config.volumes[target]
-            purgeable_snapshots = volume.purgeable_snapshots(snap_map[target])
-            purgeable_snapshots.each do |snapshot|
-              purge_snapshot(snapshot.id)
-              purged += 1
+            purgeable_snapshot_ids = volume.purgeable_snapshot_ids(snap_map[target])
+            purgeable_snapshot_ids.each do |snapshot_id|
+              to_purge += 1
+              purged += 1 if purge_snapshot(snapshot_id)
+
             end
           end
         else
@@ -128,15 +153,15 @@ def backup(args, options)
 
       end
 
-      message = "Backup Completed at #{Time.now}. Backed up #{backed_up} volume(s), max delay detected #{max_delay}, purged #{purged} snapshot(s)"
+      message = "Backup Completed at #{Time.now}. Checked #{target_volumes.count} volume(s), backed up #{backed_up}, max delay detected #{max_delay},  #{to_purge} snapshot(s), #{purged} purged"
       logger.info(message)
       puts(message)
 
     end
 
-    def calculate_target_volumes(config, args)
+    def target_volumes(args)
 
-      result = config.volume_ids
+      result = @config.volume_ids
       if (args && (args.count > 0)) then
         result &= args
       end
@@ -145,36 +170,31 @@ def calculate_target_volumes(config, args)
 
     end
 
-    def list_volumes
-      response = @ec2.describe_volumes
-      puts(response)
-    end
-
     def init_logger(options)
       Logging.log_to_file(options.logfile) unless options.logfile.nil?
     end
 
-    def backup_volume(volume_id, current_time_utc, tags)
+# backs up a given volume using the given time as part of the name and setting the given tags to the snapshot
+# @param volume_id [String] the id of the volume to be backed up
+# @param tags [Array] an array of String to be used as tags for the snapshot
+# @return [boolean] true if the backup was successful, false otherwise
+    def backup_volume(volume_id, tags)
       begin
         volume_info = @ec2.describe_volumes(:volume_id => volume_id)
 
       rescue AWS::Error => e
-        logger.warning("Volume Id #{volume_id} not found")
+        logger.error("Volume Id #{volume_id} not found. Underlying message #{e.message}")
         return false
       end
 
       begin
-        puts(volume_info)
         volume_tags = volume_info.volumeSet.item[0].tagSet.item
-        puts(volume_tags)
 
-        name_and_desc = Aebus.calculate_name_and_desc(volume_id, volume_tags, current_time_utc)
-        puts(name_and_desc)
+        name_and_desc = Core.name_and_desc(volume_id, volume_tags, @current_time_utc)
         create_response = @ec2.create_snapshot(:volume_id => volume_id, :description => name_and_desc[1])
-        puts(create_response)
 
       rescue AWS::Error => e
-        logger.error("Volume Id #{volume_id} could not be backed up")
+        logger.error("Volume Id #{volume_id} could not be backed up. Underlying message #{e.message}")
         return false
       end
 
@@ -183,18 +203,22 @@ def backup_volume(volume_id, current_time_utc, tags)
         @ec2.create_tags(:resource_id => create_response.snapshotId,
                          :tag => [{AWS_NAME_TAG => name_and_desc[0]}, {AEBUS_TAG => tags.join(',')}])
       rescue AWS::Error => e
-        logger.error("[WARNING] Could not set tags to snapshot #{create_response.snapshotId}")
+        logger.error("[WARNING] Could not set tags to snapshot #{create_response.snapshotId}. Underlying message #{e.message}")
         return false
       end
 
-      logger.info("Created snapshot #{create_response.snapshotId} for volume #{volume_id}");
+      logger.info("Created snapshot #{create_response.snapshotId} for volume #{volume_id}")
 
-      return true
+      true
 
     end
 
-
-    def self.calculate_name_and_desc(volume_id, tags, utc_time)
+# calculates the name and the description to be set to a snapshot
+# @param volume_id [String] the id of the volume whose snapshot we are creating
+# @param tags [Array] the tags currently associated with the Volume
+# @param utc_time [Time] the UTC time at which the backup process started (used to generate the correct name)
+# @return [Array] an array in the form of [name, description]]
+    def self.name_and_desc(volume_id, tags, utc_time)
 
       name = "backup_#{utc_time.strftime("%Y%m%d")}_#{volume_id}"
       volume_name = volume_id
@@ -238,9 +262,13 @@ def purge_snapshot(snapshot_id)
         response = @ec2.delete_snapshot(:snapshot_id => snapshot_id)
         if (response["return"]) then
           logger.info("Purged snapshot #{snapshot_id}")
+          true
+        else
+          false
         end
       rescue AWS::Error => e
-        logger.warn("Could not purge snapshot #{snapshot_id}")
+        logger.warn("Could not purge snapshot #{snapshot_id}; underlying message #{e.message}")
+        false
       end
 
     end

lib/aebus/volume_status.rb

@@ -0,0 +1,23 @@
+module Aebus
+
+  class VolumeStatus
+
+    attr_accessor :id, :last_backup, :next_backup, :delay, :purgeable_snapshot_ids, :tags
+
+    def initialize(volume_id)
+       @id = volume_id
+    end
+
+    def needs_backup?
+      (!@tags.nil? && (@tags.count > 0))
+    end
+
+    def to_s
+      "Volume: id => #{id}, :last_backup => #{last_backup}, next_backup=> #{next_backup}, needs_backup? => #{needs_backup?}, delay => #{delay}, tags => #{tags}, purgeable_snapshot => #{purgeable_snapshots}"
+
+
+    end
+
+  end
+
+end

lib/config/volume.rb

@@ -16,6 +16,8 @@ def initialize (current_time_utc, label, backup_config)
           calculate_deadlines(current_time_utc, backup_config["when"])
         end
         @keep = backup_config["keep"]
+        # we use Infinity to model the keep all
+        @keep = 1.0 / 0  if (@keep.nil? || @keep.eql?(KEEP_ALL))
 
       end
 
@@ -39,7 +41,7 @@ def self.parse_backups_config(current_time_utc, backups_config)
         result = Hash.new
 
         backups_config.each_pair do |key,value|
-           result.store(key, BackupSchedule.new(current_time_utc, key, value))
+          result.store(key, BackupSchedule.new(current_time_utc, key, value))
         end
 
         result
@@ -68,10 +70,10 @@ def backups_to_be_run(snapshots,current_time_utc)
         max_delay = 0
         @backups.each_pair do |k,v|
 
-           unless recent_backup?(k, snapshots, v.last_deadline)
-             result << k
-             max_delay = [max_delay, current_time_utc.to_i - v.last_deadline.to_i].max
-           end
+          unless recent_backup?(k, snapshots, v.last_deadline)
+            result << k
+            max_delay = [max_delay, current_time_utc.to_i - v.last_deadline.to_i].max
+          end
 
         end
         [max_delay, result]
@@ -90,29 +92,39 @@ def recent_backup?(label, snapshots, last_deadline)
       end
 
 
-      def purgeable_snapshots(snapshots)
+      def purgeable_snapshot_ids(snapshots)
         return [] unless snapshots
         removables = snapshots.select{|snapshot| snapshot.aebus_removable_snapshot?}
         available_backups = @backups.each_with_object({}) { | (k, v) , h | h[k] = v.keep}
         removables.each do |snapshot|
           snapshot.aebus_tags.each do |tag|
-            if (available_backups.include? tag) then
-              if (KEEP_ALL.eql?(available_backups[tag])) then
-                snapshot.keep = true
-              elsif (available_backups[tag] > 0)  then
+            if ((available_backups.include? tag) && (available_backups[tag] > 0))  then
                 snapshot.keep = true
                 available_backups[tag] -= 1
-              end
             end
           end
         end
 
-        removables.select{|snapshot| !snapshot.keep? }
+        removables.inject([]) do |acc, snapshot|
+          acc << snapshot.id unless snapshot.keep?
+          acc
+        end
+
+      end
+
+      def last_backup
+        @backups.values.map{|backup| backup.last_deadline}.max
+      end
 
+      def next_backup
+        @backups.values.map{|backup| backup.next_deadline}.min
       end
 
+
     end
 
+
+
   end
 
 end