Add timestamps to gitlab-rake gitlab:backup:restore

Adds a new method 'puts_time' that prepends the time of a
message when printing it.  All instances of 'progress.puts'
in the gitlab:backup:restore tasks are replaced with puts_time.
Example output:
  2018-06-03 16:33:25 -0400 -- Restoring uploads ..
Closes #46448

3 files changed, 76 insertions, 58 deletions

diff --git a/changelogs/unreleased/46448-add-timestamps-for-each-stage-of-gitlab-rake-gitlab-backup-restore.yml b/changelogs/unreleased/46448-add-timestamps-for-each-stage-of-gitlab-rake-gitlab-backup-restore.yml
new file mode 100644
index 00000000000..4ce6787570a
--- /dev/null
+++ b/changelogs/unreleased/46448-add-timestamps-for-each-stage-of-gitlab-rake-gitlab-backup-restore.yml
@@ -0,0 +1,5 @@
+---
+title: Display timestamps to messages printed by gitlab:backup:restore rake tasks
+merge_request:
+author: Will Chandler
+type: changed
diff --git a/lib/tasks/gitlab/backup.rake b/lib/tasks/gitlab/backup.rake
index e96fbb64372..3a1a36e36ce 100644
--- a/lib/tasks/gitlab/backup.rake
+++ b/lib/tasks/gitlab/backup.rake
@@ -47,9 +47,9 @@ namespace :gitlab do
 
           # Drop all tables Load the schema to ensure we don't have any newer tables
           # hanging out from a failed upgrade
-          progress.puts 'Cleaning the database ... '.color(:blue)
+          puts_time 'Cleaning the database ... '.color(:blue)
           Rake::Task['gitlab:db:drop_tables'].invoke
-          progress.puts 'done'.color(:green)
+          puts_time 'done'.color(:green)
           Rake::Task['gitlab:backup:db:restore'].invoke
         rescue Gitlab::TaskAbortedByUserError
           puts "Quitting...".color(:red)
@@ -72,165 +72,169 @@ namespace :gitlab do
 
     namespace :repo do
       task create: :gitlab_environment do
-        progress.puts "Dumping repositories ...".color(:blue)
+        puts_time "Dumping repositories ...".color(:blue)
 
         if ENV["SKIP"] && ENV["SKIP"].include?("repositories")
-          progress.puts "[SKIPPED]".color(:cyan)
+          puts_time "[SKIPPED]".color(:cyan)
         else
           Backup::Repository.new(progress).dump
-          progress.puts "done".color(:green)
+          puts_time "done".color(:green)
         end
       end
 
       task restore: :gitlab_environment do
-        progress.puts "Restoring repositories ...".color(:blue)
+        puts_time "Restoring repositories ...".color(:blue)
         Backup::Repository.new(progress).restore
-        progress.puts "done".color(:green)
+        puts_time "done".color(:green)
       end
     end
 
     namespace :db do
       task create: :gitlab_environment do
-        progress.puts "Dumping database ... ".color(:blue)
+        puts_time "Dumping database ... ".color(:blue)
 
         if ENV["SKIP"] && ENV["SKIP"].include?("db")
-          progress.puts "[SKIPPED]".color(:cyan)
+          puts_time "[SKIPPED]".color(:cyan)
         else
           Backup::Database.new(progress).dump
-          progress.puts "done".color(:green)
+          puts_time "done".color(:green)
         end
       end
 
       task restore: :gitlab_environment do
-        progress.puts "Restoring database ... ".color(:blue)
+        puts_time "Restoring database ... ".color(:blue)
         Backup::Database.new(progress).restore
-        progress.puts "done".color(:green)
+        puts_time "done".color(:green)
       end
     end
 
     namespace :builds do
       task create: :gitlab_environment do
-        progress.puts "Dumping builds ... ".color(:blue)
+        puts_time "Dumping builds ... ".color(:blue)
 
         if ENV["SKIP"] && ENV["SKIP"].include?("builds")
-          progress.puts "[SKIPPED]".color(:cyan)
+          puts_time "[SKIPPED]".color(:cyan)
         else
           Backup::Builds.new(progress).dump
-          progress.puts "done".color(:green)
+          puts_time "done".color(:green)
         end
       end
 
       task restore: :gitlab_environment do
-        progress.puts "Restoring builds ... ".color(:blue)
+        puts_time "Restoring builds ... ".color(:blue)
         Backup::Builds.new(progress).restore
-        progress.puts "done".color(:green)
+        puts_time "done".color(:green)
       end
     end
 
     namespace :uploads do
       task create: :gitlab_environment do
-        progress.puts "Dumping uploads ... ".color(:blue)
+        puts_time "Dumping uploads ... ".color(:blue)
 
         if ENV["SKIP"] && ENV["SKIP"].include?("uploads")
-          progress.puts "[SKIPPED]".color(:cyan)
+          puts_time "[SKIPPED]".color(:cyan)
         else
           Backup::Uploads.new(progress).dump
-          progress.puts "done".color(:green)
+          puts_time "done".color(:green)
         end
       end
 
       task restore: :gitlab_environment do
-        progress.puts "Restoring uploads ... ".color(:blue)
+        puts_time "Restoring uploads ... ".color(:blue)
         Backup::Uploads.new(progress).restore
-        progress.puts "done".color(:green)
+        puts_time "done".color(:green)
       end
     end
 
     namespace :artifacts do
       task create: :gitlab_environment do
-        progress.puts "Dumping artifacts ... ".color(:blue)
+        puts_time "Dumping artifacts ... ".color(:blue)
 
         if ENV["SKIP"] && ENV["SKIP"].include?("artifacts")
-          progress.puts "[SKIPPED]".color(:cyan)
+          puts_time "[SKIPPED]".color(:cyan)
         else
           Backup::Artifacts.new(progress).dump
-          progress.puts "done".color(:green)
+          puts_time "done".color(:green)
         end
       end
 
       task restore: :gitlab_environment do
-        progress.puts "Restoring artifacts ... ".color(:blue)
+        puts_time "Restoring artifacts ... ".color(:blue)
         Backup::Artifacts.new(progress).restore
-        progress.puts "done".color(:green)
+        puts_time "done".color(:green)
       end
     end
 
     namespace :pages do
       task create: :gitlab_environment do
-        progress.puts "Dumping pages ... ".color(:blue)
+        puts_time "Dumping pages ... ".color(:blue)
 
         if ENV["SKIP"] && ENV["SKIP"].include?("pages")
-          progress.puts "[SKIPPED]".color(:cyan)
+          puts_time "[SKIPPED]".color(:cyan)
         else
           Backup::Pages.new(progress).dump
-          progress.puts "done".color(:green)
+          puts_time "done".color(:green)
         end
       end
 
       task restore: :gitlab_environment do
-        progress.puts "Restoring pages ... ".color(:blue)
+        puts_time "Restoring pages ... ".color(:blue)
         Backup::Pages.new(progress).restore
-        progress.puts "done".color(:green)
+        puts_time "done".color(:green)
       end
     end
 
     namespace :lfs do
       task create: :gitlab_environment do
-        progress.puts "Dumping lfs objects ... ".color(:blue)
+        puts_time "Dumping lfs objects ... ".color(:blue)
 
         if ENV["SKIP"] && ENV["SKIP"].include?("lfs")
-          progress.puts "[SKIPPED]".color(:cyan)
+          puts_time "[SKIPPED]".color(:cyan)
         else
           Backup::Lfs.new(progress).dump
-          progress.puts "done".color(:green)
+          puts_time "done".color(:green)
         end
       end
 
       task restore: :gitlab_environment do
-        progress.puts "Restoring lfs objects ... ".color(:blue)
+        puts_time "Restoring lfs objects ... ".color(:blue)
         Backup::Lfs.new(progress).restore
-        progress.puts "done".color(:green)
+        puts_time "done".color(:green)
       end
     end
 
     namespace :registry do
       task create: :gitlab_environment do
-        progress.puts "Dumping container registry images ... ".color(:blue)
+        puts_time "Dumping container registry images ... ".color(:blue)
 
         if Gitlab.config.registry.enabled
           if ENV["SKIP"] && ENV["SKIP"].include?("registry")
-            progress.puts "[SKIPPED]".color(:cyan)
+            puts_time "[SKIPPED]".color(:cyan)
           else
             Backup::Registry.new(progress).dump
-            progress.puts "done".color(:green)
+            puts_time "done".color(:green)
           end
         else
-          progress.puts "[DISABLED]".color(:cyan)
+          puts_time "[DISABLED]".color(:cyan)
         end
       end
 
       task restore: :gitlab_environment do
-        progress.puts "Restoring container registry images ... ".color(:blue)
+        puts_time "Restoring container registry images ... ".color(:blue)
 
         if Gitlab.config.registry.enabled
           Backup::Registry.new(progress).restore
-          progress.puts "done".color(:green)
+          puts_time "done".color(:green)
         else
-          progress.puts "[DISABLED]".color(:cyan)
+          puts_time "[DISABLED]".color(:cyan)
         end
       end
     end
 
+    def puts_time(msg)
+      progress.puts "#{Time.now} -- #{msg}"
+    end
+
     def progress
       if ENV['CRON']
         # We need an object we can say 'puts' and 'print' to; let's use a
diff --git a/spec/tasks/gitlab/backup_rake_spec.rb b/spec/tasks/gitlab/backup_rake_spec.rb
index c9252bebb2e..70f3d77dc98 100644
--- a/spec/tasks/gitlab/backup_rake_spec.rb
+++ b/spec/tasks/gitlab/backup_rake_spec.rb
@@ -71,20 +71,29 @@ describe 'gitlab:app namespace rake task' do
         end.to raise_error(SystemExit)
       end
 
-      it 'invokes restoration on match' do
-        allow(YAML).to receive(:load_file)
-          .and_return({ gitlab_version: gitlab_version })
-        expect(Rake::Task['gitlab:db:drop_tables']).to receive(:invoke)
-        expect(Rake::Task['gitlab:backup:db:restore']).to receive(:invoke)
-        expect(Rake::Task['gitlab:backup:repo:restore']).to receive(:invoke)
-        expect(Rake::Task['gitlab:backup:builds:restore']).to receive(:invoke)
-        expect(Rake::Task['gitlab:backup:uploads:restore']).to receive(:invoke)
-        expect(Rake::Task['gitlab:backup:artifacts:restore']).to receive(:invoke)
-        expect(Rake::Task['gitlab:backup:pages:restore']).to receive(:invoke)
-        expect(Rake::Task['gitlab:backup:lfs:restore']).to receive(:invoke)
-        expect(Rake::Task['gitlab:backup:registry:restore']).to receive(:invoke)
-        expect(Rake::Task['gitlab:shell:setup']).to receive(:invoke)
-        expect { run_rake_task('gitlab:backup:restore') }.to output.to_stdout
+      context 'restore with matching gitlab version' do
+        before do
+          allow(YAML).to receive(:load_file)
+            .and_return({ gitlab_version: gitlab_version })
+          expect(Rake::Task['gitlab:db:drop_tables']).to receive(:invoke)
+          expect(Rake::Task['gitlab:backup:db:restore']).to receive(:invoke)
+          expect(Rake::Task['gitlab:backup:repo:restore']).to receive(:invoke)
+          expect(Rake::Task['gitlab:backup:builds:restore']).to receive(:invoke)
+          expect(Rake::Task['gitlab:backup:uploads:restore']).to receive(:invoke)
+          expect(Rake::Task['gitlab:backup:artifacts:restore']).to receive(:invoke)
+          expect(Rake::Task['gitlab:backup:pages:restore']).to receive(:invoke)
+          expect(Rake::Task['gitlab:backup:lfs:restore']).to receive(:invoke)
+          expect(Rake::Task['gitlab:backup:registry:restore']).to receive(:invoke)
+          expect(Rake::Task['gitlab:shell:setup']).to receive(:invoke)
+        end
+
+        it 'invokes restoration on match' do
+          expect { run_rake_task('gitlab:backup:restore') }.to output.to_stdout
+        end
+
+        it 'prints timestamps on messages' do
+          expect { run_rake_task('gitlab:backup:restore') }.to output(/.*\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}\s[-+]\d{4}\s--\s.*/).to_stdout
+        end
       end
     end
   end # backup_restore task