Log PostgreSQL errors

Flag errors from psql when restoring from backups

When a database restore from PostgreSQL finishes, it's easy to miss
important errors that cause significant issues down the road. For
example, in https://gitlab.com/gitlab-org/gitlab/-/issues/36405, the
primary key constraint in `application_settings` was not able to be
created due to duplicate keys present.

With this change, we now:

1. Track all messages from stderr

2. Filter out messages with `does not exist`. These are present because
`pg_dump` is run with the `--clean` argument to issue DROP statements,
but `--if-exists` will filter this out automatically
(https://gitlab.com/gitlab-org/gitlab/-/merge_requests/40792).

3. If there are any error messages, play them back to the user with
a warning that these errors may impact GitLab.

4. Prompt the user to continue.

.gitlab/ci/rails.gitlab-ci.yml

@@ -296,6 +296,21 @@ gitlab:setup:
     paths:
       - log/*.log
 
+db:backup_and_restore:
+  extends: .db-job-base
+  variables:
+    SETUP_DB: "false"
+    GITLAB_ASSUME_YES: "1"
+  script:
+    - . scripts/prepare_build.sh
+    - bundle exec rake db:drop db:create db:structure:load db:seed_fu
+    - mkdir -p tmp/tests/public/uploads tmp/tests/{artifacts,pages,lfs-objects,registry}
+    - bundle exec rake gitlab:backup:create
+    - date
+    - bundle exec rake gitlab:backup:restore
+  rules:
+    - changes: ["lib/backup/**/*"]
+
 rspec:coverage:
   extends:
     - .rails-job-base

changelogs/unreleased/sh-log-psql-errors.yml

+---
+title: Flag errors from psql when restoring from backups
+merge_request: 40911
+author:
+type: fixed

doc/raketasks/backup_restore.md

@@ -295,6 +295,24 @@ For installations from source:
 sudo -u git -H bundle exec rake gitlab:backup:create SKIP=tar RAILS_ENV=production
 ```
 
+#### Disabling prompts during restore
+
+During a restore from backup, the restore script may ask for confirmation before
+proceeding. If you wish to disable these prompts, you can set the `GITLAB_ASSUME_YES`
+environment variable to `1`.
+
+For Omnibus GitLab packages:
+
+```shell
+sudo GITLAB_ASSUME_YES=1 gitlab-backup restore
+```
+
+For installations from source:
+
+```shell
+sudo -u git -H GITLAB_ASSUME_YES=1 bundle exec rake gitlab:backup:restore RAILS_ENV=production
+```
+
 #### Back up Git repositories concurrently
 
 > [Introduced](https://gitlab.com/gitlab-org/gitlab/-/merge_requests/37158) in GitLab 13.3.

lib/backup/database.rb

@@ -8,10 +8,10 @@ module Backup
     attr_reader :progress
     attr_reader :config, :db_file_name
 
-    def initialize(progress)
+    def initialize(progress, filename: nil)
       @progress = progress
       @config = YAML.load_file(File.join(Rails.root, 'config', 'database.yml'))[Rails.env]
-      @db_file_name = File.join(Gitlab.config.backup.path, 'db', 'database.sql.gz')
+      @db_file_name = filename || File.join(Gitlab.config.backup.path, 'db', 'database.sql.gz')
     end
 
     def dump
@@ -57,26 +57,63 @@ module Backup
       decompress_pid = spawn(*%w(gzip -cd), out: decompress_wr, in: db_file_name)
       decompress_wr.close
 
-      restore_pid =
+      status, errors =
         case config["adapter"]
         when "postgresql" then
           progress.print "Restoring PostgreSQL database #{config['database']} ... "
           pg_env
-          spawn('psql', config['database'], in: decompress_rd)
+          execute_and_track_errors(pg_restore_cmd, decompress_rd)
         end
       decompress_rd.close
 
-      success = [decompress_pid, restore_pid].all? do |pid|
-        Process.waitpid(pid)
-        $?.success?
+      Process.waitpid(decompress_pid)
+      success = $?.success? && status.success?
+
+      if errors.present?
+        progress.print "------ BEGIN ERRORS -----".color(:yellow)
+        progress.print errors.join.color(:yellow)
+        progress.print "------ END ERRORS -------".color(:yellow)
       end
 
       report_success(success)
-      abort 'Restore failed' unless success
+      raise Backup::Error, 'Restore failed' unless success
+
+      errors
     end
 
     protected
 
+    def execute_and_track_errors(cmd, decompress_rd)
+      errors = []
+
+      Open3.popen3(ENV, *cmd) do |stdin, stdout, stderr, thread|
+        stdin.binmode
+
+        Thread.new do
+          data = stdout.read
+          $stdout.write(data)
+        end
+
+        Thread.new do
+          until (raw_line = stderr.gets).nil?
+            warn(raw_line)
+            # Recent database dumps will use --if-exists with pg_dump
+            errors << raw_line unless raw_line =~ /does not exist$/
+          end
+        end
+
+        begin
+          IO.copy_stream(decompress_rd, stdin)
+        rescue Errno::EPIPE
+        end
+
+        stdin.close
+
+        thread.join
+        [thread.value, errors]
+      end
+    end
+
     def pg_env
       args = {
         'username'  => 'PGUSER',
@@ -101,5 +138,11 @@ module Backup
         progress.puts '[FAILED]'.color(:red)
       end
     end
+
+    private
+
+    def pg_restore_cmd
+      ['psql', config['database']]
+    end
   end
 end

lib/gitlab/task_helpers.rb

@@ -24,6 +24,8 @@ module Gitlab
     # Returns "yes" the user chose to continue
     # Raises Gitlab::TaskAbortedByUserError if the user chose *not* to continue
     def ask_to_continue
+      return if Gitlab::Utils.to_boolean(ENV['GITLAB_ASSUME_YES'])
+
       answer = prompt("Do you want to continue (yes/no)? ".color(:blue), %w{yes no})
       raise Gitlab::TaskAbortedByUserError unless answer == "yes"
     end

lib/tasks/gitlab/backup.rake

@@ -136,7 +136,21 @@ namespace :gitlab do
 
       task restore: :gitlab_environment do
         puts_time "Restoring database ... ".color(:blue)
-        Backup::Database.new(progress).restore
+        errors = Backup::Database.new(progress).restore
+
+        if errors.present?
+          warning = <<~MSG
+            There were errors in restoring the schema. This may cause
+            issues if this results in missing indexes, constraints, or
+            columns. Please record the errors above and contact GitLab
+            Support if you have questions:
+            https://about.gitlab.com/support/
+          MSG
+
+          warn warning.color(:red)
+          ask_to_continue
+        end
+
         puts_time "done".color(:green)
       end
     end

spec/lib/backup/database_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe Backup::Database do
+  let(:progress) { StringIO.new }
+  let(:output) { progress.string }
+
+  describe '#restore' do
+    let(:cmd) { %W[#{Gem.ruby} -e $stdout.puts(1)] }
+    let(:data) { Rails.root.join("spec/fixtures/pages_empty.tar.gz").to_s }
+
+    subject { described_class.new(progress, filename: data) }
+
+    before do
+      allow(subject).to receive(:pg_restore_cmd).and_return(cmd)
+    end
+
+    context 'with an empty .gz file' do
+      let(:data) { Rails.root.join("spec/fixtures/pages_empty.tar.gz").to_s }
+
+      it 'returns successfully' do
+        expect(subject.restore).to eq([])
+
+        expect(output).to include("Restoring PostgreSQL database")
+        expect(output).to include("[DONE]")
+        expect(output).not_to include("ERRORS")
+      end
+    end
+
+    context 'with a corrupted .gz file' do
+      let(:data) { Rails.root.join("spec/fixtures/big-image.png").to_s }
+
+      it 'raises a backup error' do
+        expect { subject.restore }.to raise_error(Backup::Error)
+      end
+    end
+
+    context 'when the restore command prints errors' do
+      let(:visible_error) { "This is a test error\n" }
+      let(:noise) { "Table projects does not exist\n" }
+      let(:cmd) { %W[#{Gem.ruby} -e $stderr.write("#{noise}#{visible_error}")] }
+
+      it 'filters out noise from errors' do
+        expect(subject.restore).to eq([visible_error])
+        expect(output).to include("ERRORS")
+        expect(output).not_to include(noise)
+        expect(output).to include(visible_error)
+      end
+    end
+  end
+end