Improve backup logging

Migrates most logging output generated by the backup manager to the new
backup log file. Previously logging was sometimes logged and other times
outputted directly to stdout.

Changelog: fixed

lib/backup/manager.rb

@@ -88,34 +88,33 @@ module Backup
         remove_old
       end
 
-      progress.puts "Warning: Your gitlab.rb and gitlab-secrets.json files contain sensitive data \n" \
+      puts_time "Warning: Your gitlab.rb and gitlab-secrets.json files contain sensitive data \n" \
            "and are not included in this backup. You will need these files to restore a backup.\n" \
            "Please back them up manually.".color(:red)
-      progress.puts "Backup task is done."
+      puts_time "Backup task is done."
     end
 
     def run_create_task(task_name)
       definition = @definitions[task_name]
 
       build_backup_information
-      puts_time "Dumping #{definition.task.human_name} ... ".color(:blue)
 
       unless definition.task.enabled
-        puts_time "[DISABLED]".color(:cyan)
+        puts_time "Dumping #{definition.task.human_name} ... ".color(:blue) + "[DISABLED]".color(:cyan)
         return
       end
 
       if skipped?(task_name)
-        puts_time "[SKIPPED]".color(:cyan)
+        puts_time "Dumping #{definition.task.human_name} ... ".color(:blue) + "[SKIPPED]".color(:cyan)
         return
       end
 
+      puts_time "Dumping #{definition.task.human_name} ... ".color(:blue)
       definition.task.dump(File.join(Gitlab.config.backup.path, definition.destination_path))
-
-      puts_time "done".color(:green)
+      puts_time "Dumping #{definition.task.human_name} ... ".color(:blue) + "done".color(:green)
 
     rescue Backup::DatabaseBackupError, Backup::FileBackupError => e
-      progress.puts "#{e.message}"
+      puts_time "Dumping #{definition.task.human_name} failed: #{e.message}".color(:red)
     end
 
     def restore
@@ -136,21 +135,21 @@ module Backup
 
       remove_tmp
 
-      puts "Warning: Your gitlab.rb and gitlab-secrets.json files contain sensitive data \n" \
-           "and are not included in this backup. You will need to restore these files manually.".color(:red)
-      puts "Restore task is done."
+      puts_time "Warning: Your gitlab.rb and gitlab-secrets.json files contain sensitive data \n" \
+        "and are not included in this backup. You will need to restore these files manually.".color(:red)
+      puts_time "Restore task is done."
     end
 
     def run_restore_task(task_name)
       definition = @definitions[task_name]
 
-      puts_time "Restoring #{definition.task.human_name} ... ".color(:blue)
-
       unless definition.task.enabled
-        puts_time "[DISABLED]".color(:cyan)
+        puts_time "Restoring #{definition.task.human_name} ... ".color(:blue) + "[DISABLED]".color(:cyan)
         return
       end
 
+      puts_time "Restoring #{definition.task.human_name} ... ".color(:blue)
+
       warning = definition.task.pre_restore_warning
       if warning.present?
         puts_time warning.color(:red)
@@ -159,7 +158,7 @@ module Backup
 
       definition.task.restore(File.join(Gitlab.config.backup.path, definition.destination_path))
 
-      puts_time "done".color(:green)
+      puts_time "Restoring #{definition.task.human_name} ... ".color(:blue) + "done".color(:green)
 
       warning = definition.task.post_restore_warning
       if warning.present?
@@ -209,103 +208,107 @@ module Backup
     def pack
       Dir.chdir(backup_path) do
         # create archive
-        progress.print "Creating backup archive: #{tar_file} ... "
+        puts_time "Creating backup archive: #{tar_file} ... ".color(:blue)
         # Set file permissions on open to prevent chmod races.
         tar_system_options = { out: [tar_file, 'w', Gitlab.config.backup.archive_permissions] }
         if Kernel.system('tar', '-cf', '-', *backup_contents, tar_system_options)
-          progress.puts "done".color(:green)
+          puts_time "Creating backup archive: #{tar_file} ... ".color(:blue) + 'done'.color(:green)
         else
-          puts "creating archive #{tar_file} failed".color(:red)
+          puts_time "Creating archive #{tar_file} failed".color(:red)
           raise Backup::Error, 'Backup failed'
         end
       end
     end
 
     def upload
-      progress.print "Uploading backup archive to remote storage #{remote_directory} ... "
-
       connection_settings = Gitlab.config.backup.upload.connection
       if connection_settings.blank?
-        progress.puts "skipped".color(:yellow)
+        puts_time "Uploading backup archive to remote storage #{remote_directory} ... ".color(:blue) + "[SKIPPED]".color(:cyan)
         return
       end
 
+      puts_time "Uploading backup archive to remote storage #{remote_directory} ... ".color(:blue)
+
       directory = connect_to_remote_directory
       upload = directory.files.create(create_attributes)
 
       if upload
         if upload.respond_to?(:encryption) && upload.encryption
-          progress.puts "done (encrypted with #{upload.encryption})".color(:green)
+          puts_time "Uploading backup archive to remote storage #{remote_directory} ... ".color(:blue) + "done (encrypted with #{upload.encryption})".color(:green)
         else
-          progress.puts "done".color(:green)
+          puts_time "Uploading backup archive to remote storage #{remote_directory} ... ".color(:blue) + "done".color(:green)
         end
       else
-        puts "uploading backup to #{remote_directory} failed".color(:red)
+        puts_time "Uploading backup to #{remote_directory} failed".color(:red)
         raise Backup::Error, 'Backup failed'
       end
     end
 
     def cleanup
-      progress.print "Deleting tmp directories ... "
+      puts_time "Deleting tar staging files ... ".color(:blue)
 
       remove_backup_path(MANIFEST_NAME)
       @definitions.each do |_, definition|
         remove_backup_path(definition.cleanup_path || definition.destination_path)
       end
+
+      puts_time "Deleting tar staging files ... ".color(:blue) + 'done'.color(:green)
     end
 
     def remove_backup_path(path)
-      return unless File.exist?(File.join(backup_path, path))
+      absolute_path = File.join(backup_path, path)
+      return unless File.exist?(absolute_path)
 
-      FileUtils.rm_rf(File.join(backup_path, path))
-      progress.puts "done".color(:green)
+      puts_time "Cleaning up #{absolute_path}"
+      FileUtils.rm_rf(absolute_path)
     end
 
     def remove_tmp
       # delete tmp inside backups
-      progress.print "Deleting backups/tmp ... "
+      puts_time "Deleting backups/tmp ... ".color(:blue)
 
       if FileUtils.rm_rf(File.join(backup_path, "tmp"))
-        progress.puts "done".color(:green)
+        puts_time "Deleting backups/tmp ... ".color(:blue) + "done".color(:green)
       else
-        puts "deleting backups/tmp failed".color(:red)
+        puts_time "Deleting backups/tmp failed".color(:red)
       end
     end
 
     def remove_old
       # delete backups
-      progress.print "Deleting old backups ... "
       keep_time = Gitlab.config.backup.keep_time.to_i
 
-      if keep_time > 0
-        removed = 0
-
-        Dir.chdir(backup_path) do
-          backup_file_list.each do |file|
-            # For backward compatibility, there are 3 names the backups can have:
-            # - 1495527122_gitlab_backup.tar
-            # - 1495527068_2017_05_23_gitlab_backup.tar
-            # - 1495527097_2017_05_23_9.3.0-pre_gitlab_backup.tar
-            matched = backup_file?(file)
-            next unless matched
-
-            timestamp = matched[1].to_i
-
-            if Time.at(timestamp) < (Time.now - keep_time)
-              begin
-                FileUtils.rm(file)
-                removed += 1
-              rescue StandardError => e
-                progress.puts "Deleting #{file} failed: #{e.message}".color(:red)
-              end
+      if keep_time <= 0
+        puts_time "Deleting old backups ... ".color(:blue) + "[SKIPPED]".color(:cyan)
+        return
+      end
+
+      puts_time "Deleting old backups ... ".color(:blue)
+      removed = 0
+
+      Dir.chdir(backup_path) do
+        backup_file_list.each do |file|
+          # For backward compatibility, there are 3 names the backups can have:
+          # - 1495527122_gitlab_backup.tar
+          # - 1495527068_2017_05_23_gitlab_backup.tar
+          # - 1495527097_2017_05_23_9.3.0-pre_gitlab_backup.tar
+          matched = backup_file?(file)
+          next unless matched
+
+          timestamp = matched[1].to_i
+
+          if Time.at(timestamp) < (Time.now - keep_time)
+            begin
+              FileUtils.rm(file)
+              removed += 1
+            rescue StandardError => e
+              puts_time "Deleting #{file} failed: #{e.message}".color(:red)
             end
           end
         end
-
-        progress.puts "done. (#{removed} removed)".color(:green)
-      else
-        progress.puts "skipping".color(:yellow)
       end
+
+      puts_time "Deleting old backups ... ".color(:blue) + "done. (#{removed} removed)".color(:green)
     end
 
     def verify_backup_version
@@ -327,7 +330,7 @@ module Backup
 
     def unpack
       if ENV['BACKUP'].blank? && non_tarred_backup?
-        progress.puts "Non tarred backup found in #{backup_path}, using that"
+        puts_time "Non tarred backup found in #{backup_path}, using that"
 
         return false
       end
@@ -335,15 +338,15 @@ module Backup
       Dir.chdir(backup_path) do
         # check for existing backups in the backup dir
         if backup_file_list.empty?
-          progress.puts "No backups found in #{backup_path}"
-          progress.puts "Please make sure that file name ends with #{FILE_NAME_SUFFIX}"
+          puts_time "No backups found in #{backup_path}"
+          puts_time "Please make sure that file name ends with #{FILE_NAME_SUFFIX}"
           exit 1
         elsif backup_file_list.many? && ENV["BACKUP"].nil?
-          progress.puts 'Found more than one backup:'
+          puts_time 'Found more than one backup:'
           # print list of available backups
-          progress.puts " " + available_timestamps.join("\n ")
-          progress.puts 'Please specify which one you want to restore:'
-          progress.puts 'rake gitlab:backup:restore BACKUP=timestamp_of_backup'
+          puts_time " " + available_timestamps.join("\n ")
+          puts_time 'Please specify which one you want to restore:'
+          puts_time 'rake gitlab:backup:restore BACKUP=timestamp_of_backup'
           exit 1
         end
 
@@ -354,16 +357,16 @@ module Backup
                    end
 
         unless File.exist?(tar_file)
-          progress.puts "The backup file #{tar_file} does not exist!"
+          puts_time "The backup file #{tar_file} does not exist!"
           exit 1
         end
 
-        progress.print 'Unpacking backup ... '
+        puts_time 'Unpacking backup ... '.color(:blue)
 
         if Kernel.system(*%W(tar -xf #{tar_file}))
-          progress.puts 'done'.color(:green)
+          puts_time 'Unpacking backup ... '.color(:blue) + 'done'.color(:green)
         else
-          progress.puts 'unpacking backup failed'.color(:red)
+          puts_time 'Unpacking backup failed'.color(:red)
           exit 1
         end
       end

spec/lib/backup/manager_spec.rb

@@ -28,7 +28,7 @@ RSpec.describe Backup::Manager do
     it 'calls the named task' do
       expect(task).to receive(:dump)
       expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Dumping my task ... ')
-      expect(Gitlab::BackupLogger).to receive(:info).with(message: 'done')
+      expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Dumping my task ... done')
 
       subject.run_create_task('my_task')
     end
@@ -37,8 +37,7 @@ RSpec.describe Backup::Manager do
       let(:enabled) { false }
 
       it 'informs the user' do
-        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Dumping my task ... ')
-        expect(Gitlab::BackupLogger).to receive(:info).with(message: '[DISABLED]')
+        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Dumping my task ... [DISABLED]')
 
         subject.run_create_task('my_task')
       end
@@ -48,8 +47,7 @@ RSpec.describe Backup::Manager do
       it 'informs the user' do
         stub_env('SKIP', 'my_task')
 
-        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Dumping my task ... ')
-        expect(Gitlab::BackupLogger).to receive(:info).with(message: '[SKIPPED]')
+        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Dumping my task ... [SKIPPED]')
 
         subject.run_create_task('my_task')
       end
@@ -78,7 +76,7 @@ RSpec.describe Backup::Manager do
     it 'calls the named task' do
       expect(task).to receive(:restore)
       expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Restoring my task ... ').ordered
-      expect(Gitlab::BackupLogger).to receive(:info).with(message: 'done').ordered
+      expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Restoring my task ... done').ordered
 
       subject.run_restore_task('my_task')
     end
@@ -87,8 +85,7 @@ RSpec.describe Backup::Manager do
       let(:enabled) { false }
 
       it 'informs the user' do
-        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Restoring my task ... ').ordered
-        expect(Gitlab::BackupLogger).to receive(:info).with(message: '[DISABLED]').ordered
+        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Restoring my task ... [DISABLED]').ordered
 
         subject.run_restore_task('my_task')
       end
@@ -100,7 +97,7 @@ RSpec.describe Backup::Manager do
       it 'displays and waits for the user' do
         expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Restoring my task ... ').ordered
         expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Watch out!').ordered
-        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'done').ordered
+        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Restoring my task ... done').ordered
         expect(Gitlab::TaskHelpers).to receive(:ask_to_continue)
         expect(task).to receive(:restore)
 
@@ -124,7 +121,7 @@ RSpec.describe Backup::Manager do
 
       it 'displays and waits for the user' do
         expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Restoring my task ... ').ordered
-        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'done').ordered
+        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Restoring my task ... done').ordered
         expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Watch out!').ordered
         expect(Gitlab::TaskHelpers).to receive(:ask_to_continue)
         expect(task).to receive(:restore)
@@ -134,7 +131,7 @@ RSpec.describe Backup::Manager do
 
       it 'does not continue when the user quits' do
         expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Restoring my task ... ').ordered
-        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'done').ordered
+        expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Restoring my task ... done').ordered
         expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Watch out!').ordered
         expect(Gitlab::BackupLogger).to receive(:info).with(message: 'Quitting...').ordered
         expect(task).to receive(:restore)
@@ -248,6 +245,7 @@ RSpec.describe Backup::Manager do
       end
 
       before do
+        allow(Gitlab::BackupLogger).to receive(:info)
         allow(Dir).to receive(:chdir).and_yield
         allow(Dir).to receive(:glob).and_return(files)
         allow(FileUtils).to receive(:rm)
@@ -266,7 +264,7 @@ RSpec.describe Backup::Manager do
         end
 
         it 'prints a skipped message' do
-          expect(progress).to have_received(:puts).with('skipping')
+          expect(Gitlab::BackupLogger).to have_received(:info).with(message: 'Deleting old backups ... [SKIPPED]')
         end
       end
 
@@ -290,7 +288,7 @@ RSpec.describe Backup::Manager do
         end
 
         it 'prints a done message' do
-          expect(progress).to have_received(:puts).with('done. (0 removed)')
+          expect(Gitlab::BackupLogger).to have_received(:info).with(message: 'Deleting old backups ... done. (0 removed)')
         end
       end
 
@@ -307,7 +305,7 @@ RSpec.describe Backup::Manager do
         end
 
         it 'prints a done message' do
-          expect(progress).to have_received(:puts).with('done. (0 removed)')
+          expect(Gitlab::BackupLogger).to have_received(:info).with(message: 'Deleting old backups ... done. (0 removed)')
         end
       end
 
@@ -348,7 +346,7 @@ RSpec.describe Backup::Manager do
         end
 
         it 'prints a done message' do
-          expect(progress).to have_received(:puts).with('done. (8 removed)')
+          expect(Gitlab::BackupLogger).to have_received(:info).with(message: 'Deleting old backups ... done. (8 removed)')
         end
       end
 
@@ -372,11 +370,11 @@ RSpec.describe Backup::Manager do
         end
 
         it 'sets the correct removed count' do
-          expect(progress).to have_received(:puts).with('done. (7 removed)')
+          expect(Gitlab::BackupLogger).to have_received(:info).with(message: 'Deleting old backups ... done. (7 removed)')
         end
 
         it 'prints the error from file that could not be removed' do
-          expect(progress).to have_received(:puts).with(a_string_matching(message))
+          expect(Gitlab::BackupLogger).to have_received(:info).with(message: a_string_matching(message))
         end
       end
     end
@@ -386,6 +384,7 @@ RSpec.describe Backup::Manager do
       let(:backup_filename) { File.basename(backup_file.path) }
 
       before do
+        allow(Gitlab::BackupLogger).to receive(:info)
         allow(subject).to receive(:tar_file).and_return(backup_filename)
 
         stub_backup_setting(
@@ -462,7 +461,7 @@ RSpec.describe Backup::Manager do
           it 'sets encryption attributes' do
             subject.create # rubocop:disable Rails/SaveBang
 
-            expect(progress).to have_received(:puts).with("done (encrypted with AES256)")
+            expect(Gitlab::BackupLogger).to have_received(:info).with(message: 'Uploading backup archive to remote storage directory ... done (encrypted with AES256)')
           end
         end
 
@@ -473,7 +472,7 @@ RSpec.describe Backup::Manager do
           it 'sets encryption attributes' do
             subject.create # rubocop:disable Rails/SaveBang
 
-            expect(progress).to have_received(:puts).with("done (encrypted with AES256)")
+            expect(Gitlab::BackupLogger).to have_received(:info).with(message: 'Uploading backup archive to remote storage directory ... done (encrypted with AES256)')
           end
         end
 
@@ -488,7 +487,7 @@ RSpec.describe Backup::Manager do
           it 'sets encryption attributes' do
             subject.create # rubocop:disable Rails/SaveBang
 
-            expect(progress).to have_received(:puts).with("done (encrypted with aws:kms)")
+            expect(Gitlab::BackupLogger).to have_received(:info).with(message: 'Uploading backup archive to remote storage directory ... done (encrypted with aws:kms)')
           end
         end
       end
@@ -570,6 +569,7 @@ RSpec.describe Backup::Manager do
       Rake.application.rake_require 'tasks/gitlab/shell'
       Rake.application.rake_require 'tasks/cache'
 
+      allow(Gitlab::BackupLogger).to receive(:info)
       allow(task1).to receive(:restore).with(File.join(Gitlab.config.backup.path, 'task1.tar.gz'))
       allow(task2).to receive(:restore).with(File.join(Gitlab.config.backup.path, 'task2.tar.gz'))
       allow(YAML).to receive(:load_file).with(File.join(Gitlab.config.backup.path, 'backup_information.yml'))
@@ -680,7 +680,7 @@ RSpec.describe Backup::Manager do
 
           subject.restore
 
-          expect(progress).to have_received(:print).with('Deleting backups/tmp ... ')
+          expect(Gitlab::BackupLogger).to have_received(:info).with(message: 'Deleting backups/tmp ... ')
         end
       end
     end
@@ -731,7 +731,7 @@ RSpec.describe Backup::Manager do
 
           subject.restore
 
-          expect(progress).to have_received(:print).with('Deleting backups/tmp ... ')
+          expect(Gitlab::BackupLogger).to have_received(:info).with(message: 'Deleting backups/tmp ... ')
         end
       end
     end

spec/tasks/gitlab/backup_rake_spec.rb

@@ -199,18 +199,25 @@ RSpec.describe 'gitlab:app namespace rake task', :delete do
         end
 
         it 'logs the progress to log file' do
-          expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping database ... ")
-          expect(Gitlab::BackupLogger).to receive(:info).with(message: "[SKIPPED]")
+          expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping database ... [SKIPPED]")
           expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping repositories ... ")
+          expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping repositories ... done")
           expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping uploads ... ")
+          expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping uploads ... done")
           expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping builds ... ")
+          expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping builds ... done")
           expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping artifacts ... ")
+          expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping artifacts ... done")
           expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping pages ... ")
+          expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping pages ... done")
           expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping lfs objects ... ")
+          expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping lfs objects ... done")
           expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping terraform states ... ")
+          expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping terraform states ... done")
           expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping container registry images ... ")
+          expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping container registry images ... done")
           expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping packages ... ")
-          expect(Gitlab::BackupLogger).to receive(:info).with(message: "done").exactly(9).times
+          expect(Gitlab::BackupLogger).to receive(:info).with(message: "Dumping packages ... done")
 
           backup_tasks.each do |task|
             run_rake_task("gitlab:backup:#{task}:create")