Increase backup logging

Author: joeyates

lib/imap/backup/account/backup.rb

@@ -18,27 +18,33 @@ def initialize(account:, refresh: false)
     # Runs the backup
     # @return [void]
     def run
-      Logger.logger.info "Running backup of account: #{account.username}"
+      Logger.logger.info "Running backup of account '#{account.username}'"
       # start the connection so we get logging messages in the right order
       account.client.login
 
-      Account::FolderEnsurer.new(account: account).run
-      Account::LocalOnlyFolderDeleter.new(account: account).run if account.mirror_mode
+      run_pre_backup_tasks
       backup_folders = Account::BackupFolders.new(
         client: account.client, account: account
       ).to_a
       if backup_folders.none?
-        Logger.logger.warn "Account #{account.username}: No folders found to backup"
+        Logger.logger.warn "No folders found to backup for account '#{account.username}'"
         return
       end
+      Logger.logger.debug "Starting backup of #{backup_folders.count} folders"
       backup_folders.each do |folder|
         Account::FolderBackup.new(account: account, folder: folder, refresh: refresh).run
       end
+      Logger.logger.debug "Backup of account '#{account.username}' complete"
     end
 
     private
 
     attr_reader :account
     attr_reader :refresh
+
+    def run_pre_backup_tasks
+      Account::FolderEnsurer.new(account: account).run
+      Account::LocalOnlyFolderDeleter.new(account: account).run if account.mirror_mode
+    end
   end
 end

lib/imap/backup/account/folder.rb

@@ -31,11 +31,14 @@ def initialize(client, name)
 
     # @raise any error that occurs more than 10 times
     def exist?
+      Logger.logger.debug "Checking whether folder '#{name}' exists"
       retry_on_error(errors: EXAMINE_RETRY_CLASSES) do
         examine
       end
+      Logger.logger.debug "Folder '#{name}' exists"
       true
     rescue FolderNotFound
+      Logger.logger.debug "Folder '#{name}' does not exist"
       false
     end
 
@@ -62,8 +65,11 @@ def uid_validity
     # @raise any error that occurs more than 10 times
     # @return [Array<Integer>] the folders message UIDs
     def uids
+      Logger.logger.debug "Fetching UIDs for folder '#{name}'"
       examine
-      client.uid_search(["ALL"]).sort
+      result = client.uid_search(["ALL"]).sort
+      Logger.logger.debug "#{result.count} UIDs found for folder '#{name}'"
+      result
     rescue FolderNotFound
       []
     rescue NoMethodError

lib/imap/backup/account/folder_backup.rb

@@ -22,7 +22,7 @@ def initialize(account:, folder:, refresh: false)
     # @raise [RuntimeError] if the configured download strategy is incorrect
     # @return [void]
     def run
-      Logger.logger.debug "[#{folder.name}] running backup"
+      Logger.logger.debug "Running backup for folder '#{folder.name}'"
 
       folder_ok = folder_ok?
       return if !folder_ok
@@ -36,6 +36,7 @@ def run
       # After the transaction the serializer will have any appended messages
       # so we can check differences between the server and the local backup
       LocalOnlyMessageDeleter.new(folder, raw_serializer).run if account.mirror_mode
+      Logger.logger.debug "Backup for folder '#{folder.name}' complete"
     end
 
     private
@@ -47,12 +48,12 @@ def run
     def folder_ok?
       begin
         if !folder.exist?
-          Logger.logger.info "[#{folder.name}] skipping folder as it does not exist"
+          Logger.logger.info "Skipping backup for folder '#{folder.name}' as it does not exist"
           return false
         end
       rescue Encoding::UndefinedConversionError
         message = "Skipping backup for '#{folder.name}' " \
-                  "as it is not UTF-7 encoded correctly"
+                  "as it's name is not UTF-7 encoded correctly"
         Logger.logger.info message
         return false
       end

lib/imap/backup/cli/backup.rb

@@ -24,13 +24,15 @@ def initialize(options)
     #   @return [void]
     no_commands do
       def run
+        Logger.logger.debug "Loading configuration"
         config = load_config(**options)
         exit_code = nil
         accounts = requested_accounts(config)
         if accounts.none?
           Logger.logger.warn "No matching accounts found to backup"
           return
         end
+        Logger.logger.debug "Starting backup of #{accounts.count} accounts"
         accounts.each do |account|
           backup = Account::Backup.new(account: account, refresh: refresh)
           backup.run
@@ -43,6 +45,7 @@ def run
           Logger.logger.error message
           next
         end
+        Logger.logger.debug "Backup complete"
         exit(exit_code) if exit_code
       end
     end

lib/imap/backup/client/default.rb

@@ -27,6 +27,7 @@ def initialize(server, account, options)
     # @return [Array<String>] the account folders
     def list
       root = provider_root
+      Logger.logger.debug "Listing all account folders"
       mailbox_lists = imap.list(root, "*")
 
       return [] if mailbox_lists.nil?
@@ -105,7 +106,9 @@ def masked_password
     # in the reference.
     def provider_root
       @provider_root ||= begin
+        Logger.logger.debug "Fetching provider root"
         root_info = imap.list("", "")[0]
+        Logger.logger.debug "Provider root is '#{root_info.name}'"
         root_info.name
       end
     end

lib/imap/backup/downloader.rb

@@ -19,7 +19,19 @@ def initialize(folder, serializer, multi_fetch_size: 1, reset_seen_flags_after_f
     # Runs the downloader
     # @return [void]
     def run
-      info("#{uids.count} new messages") if uids.any?
+      debug("#{serializer_uids.count} already messages already downloaded")
+      debug("#{folder_uids.count} messages on server")
+      local_only_count = (serializer_uids - folder_uids).count
+      if local_only_count.positive?
+        debug("#{local_only_count} downloaded messages no longer on server")
+      end
+
+      if uids.none?
+        debug("no new messages on server — skipping")
+        return
+      end
+
+      info("#{uids.count} new messages")
 
       uids.each_slice(multi_fetch_size).with_index do |block, i|
         multifetch_failed = download_block(block, i)
@@ -62,8 +74,8 @@ def download_block(block, index)
         end
       if uids_and_bodies.nil?
         if multi_fetch_size > 1
-          uids = block.join(", ")
-          debug("Multi fetch failed for UIDs #{uids}, switching to single fetches")
+          uid_list = block.join(", ")
+          debug("Multi fetch failed for UIDs #{uid_list}, switching to single fetches")
           return true
         else
           debug("Fetch failed for UID #{block[0]} - skipping")
@@ -96,8 +108,16 @@ def handle_uid_and_body(uid_and_body, index)
       error(e)
     end
 
+    def folder_uids
+      @folder_uids ||= folder.uids
+    end
+
+    def serializer_uids
+      @serializer_uids ||= serializer.uids
+    end
+
     def uids
-      @uids ||= folder.uids - serializer.uids
+      @uids ||= folder_uids - serializer_uids
     end
 
     def debug(message)