Failed `gitlab-backup create` to remote storage silently fails with no error

Summary

When gitlab-backup create is run and fails, the backup completes and creates a backup tar as though all went well. This leads to an incomplete backup in a bad state. Restoring this will likely cause issues.

In this issue, we focus on an upload to remote storage that fails. Manually running these backup rake tasks sometimes gives an error but not in the backup_json.log for omnibus instances.

Steps to reproduce

1. Setup a remote storage bucket - AWS S3 Bucket or GCS bucket.

2. On gitlab.rb file, enable backup to remote storage using either AWS or GCS:

   • Use Amazon S3 storage

   • Or GCS

     Example:

      gitlab_rails['backup_upload_connection'] = {
      'provider' => 'AWS',
      'region' => 'eu-west-1',
      #'aws_access_key_id' => 'AKIAKIAKI',
      # 'aws_secret_access_key' => 'secret123'
      # If using an IAM Profile, don't configure aws_access_key_id & aws_secret_access_key
       'use_iam_profile' => true
      }
      gitlab_rails['backup_upload_remote_directory'] = 'my.s3.bucket'

3. Run gitlab-ctl reconfigure

4. Backup GitLab : sudo gitlab-backup create

5. As the backup is ongoing, collect SOS logs to analyze backup_json.log:

    curl https://gitlab.com/gitlab-com/support/toolbox/gitlabsos/raw/master/gitlabsos.rb | sudo /opt/gitlab/embedded/bin/ruby

Example Project

What is the current bug behavior?

• When a backup to remote storage fails, the logs in backup_json.log does not indicate any error and silently fails. This makes it hard to detect if the uploaded file/backup was unsuccessful and why.

{"severity":"INFO","time":"2022-09-14T14:02:33.399Z","correlation_id":null,"message":"Creating backup archive: 1663164000_2022_09_14_15.2.2-ee_gitlab_backup.tar ... "}
{"severity":"INFO","time":"2022-09-14T14:02:55.694Z","correlation_id":null,"message":"Creating backup archive: 1663164000_2022_09_14_15.2.2-ee_gitlab_backup.tar ... done"}
{"severity":"INFO","time":"2022-09-14T14:02:55.697Z","correlation_id":null,"message":"Uploading backup archive to remote storage REDACTED ... "}
{"severity":"INFO","time":"2022-09-14T14:02:55.713Z","correlation_id":null,"message":"Deleting tar staging files ... "}
{"severity":"INFO","time":"2022-09-14T14:02:55.713Z","correlation_id":null,"message":"Cleaning up /var/opt/gitlab/backups/backup_information.yml"}
{"severity":"INFO","time":"2022-09-14T14:02:55.714Z","correlation_id":null,"message":"Cleaning up /var/opt/gitlab/backups/db"}
{"severity":"INFO","time":"2022-09-14T14:02:55.714Z","correlation_id":null,"message":"Cleaning up /var/opt/gitlab/backups/repositories"}
{"severity":"INFO","time":"2022-09-14T14:02:55.720Z","correlation_id":null,"message":"Cleaning up /var/opt/gitlab/backups/uploads.tar.gz"}
{"severity":"INFO","time":"2022-09-14T14:02:55.720Z","correlation_id":null,"message":"Cleaning up /var/opt/gitlab/backups/builds.tar.gz"}
{"severity":"INFO","time":"2022-09-14T14:02:55.721Z","correlation_id":null,"message":"Cleaning up /var/opt/gitlab/backups/artifacts.tar.gz"}
{"severity":"INFO","time":"2022-09-14T14:02:55.721Z","correlation_id":null,"message":"Cleaning up /var/opt/gitlab/backups/pages.tar.gz"}
{"severity":"INFO","time":"2022-09-14T14:02:55.721Z","correlation_id":null,"message":"Cleaning up /var/opt/gitlab/backups/lfs.tar.gz"}
{"severity":"INFO","time":"2022-09-14T14:02:55.722Z","correlation_id":null,"message":"Cleaning up /var/opt/gitlab/backups/terraform_state.tar.gz"}
{"severity":"INFO","time":"2022-09-14T14:02:55.722Z","correlation_id":null,"message":"Cleaning up /var/opt/gitlab/backups/registry.tar.gz"}
{"severity":"INFO","time":"2022-09-14T14:02:55.890Z","correlation_id":null,"message":"Cleaning up /var/opt/gitlab/backups/packages.tar.gz"}
{"severity":"INFO","time":"2022-09-14T14:02:55.891Z","correlation_id":null,"message":"Deleting tar staging files ... done"}
{"severity":"INFO","time":"2022-09-14T14:02:55.891Z","correlation_id":null,"message":"Deleting backups/tmp ... "}
{"severity":"INFO","time":"2022-09-14T14:02:55.891Z","correlation_id":null,"message":"Deleting backups/tmp ... done"}

• The rake task log also does not indicate ...failed or ...done but shows the error at the end.

2022-09-14 14:02:33 +0000 -- Creating backup archive: 1663164000_2022_09_14_15.2.2-ee_gitlab_backup.tar ...
2022-09-14 14:02:55 +0000 -- Creating backup archive: 1663164000_2022_09_14_15.2.2-ee_gitlab_backup.tar ... done
2022-09-14 14:02:55 +0000 -- Uploading backup archive to remote storage REDACTED ...
2022-09-14 14:02:55 +0000 -- Deleting tar staging files ...
2022-09-14 14:02:55 +0000 -- Cleaning up /var/opt/gitlab/backups/backup_information.yml
2022-09-14 14:02:55 +0000 -- Cleaning up /var/opt/gitlab/backups/db
2022-09-14 14:02:55 +0000 -- Cleaning up /var/opt/gitlab/backups/repositories
2022-09-14 14:02:55 +0000 -- Cleaning up /var/opt/gitlab/backups/uploads.tar.gz
2022-09-14 14:02:55 +0000 -- Cleaning up /var/opt/gitlab/backups/builds.tar.gz
2022-09-14 14:02:55 +0000 -- Cleaning up /var/opt/gitlab/backups/artifacts.tar.gz
2022-09-14 14:02:55 +0000 -- Cleaning up /var/opt/gitlab/backups/pages.tar.gz
2022-09-14 14:02:55 +0000 -- Cleaning up /var/opt/gitlab/backups/lfs.tar.gz
2022-09-14 14:02:55 +0000 -- Cleaning up /var/opt/gitlab/backups/terraform_state.tar.gz
2022-09-14 14:02:55 +0000 -- Cleaning up /var/opt/gitlab/backups/registry.tar.gz
2022-09-14 14:02:55 +0000 -- Cleaning up /var/opt/gitlab/backups/packages.tar.gz
2022-09-14 14:02:55 +0000 -- Deleting tar staging files ... done
2022-09-14 14:02:55 +0000 -- Deleting backups/tmp ...
2022-09-14 14:02:55 +0000 -- Deleting backups/tmp ... done
rake aborted!
ArgumentError: Missing required arguments: aws_access_key_id, aws_secret_access_key
/opt/gitlab/embedded/service/gitlab-rails/lib/backup/manager.rb:520:in `connect_to_remote_directory'
/opt/gitlab/embedded/service/gitlab-rails/lib/backup/manager.rb:323:in `upload'
/opt/gitlab/embedded/service/gitlab-rails/lib/backup/manager.rb:222:in `run_all_create_tasks'
/opt/gitlab/embedded/service/gitlab-rails/lib/backup/manager.rb:46:in `create'
/opt/gitlab/embedded/service/gitlab-rails/lib/tasks/gitlab/backup.rake:12:in `block (3 levels) in <top (required)>'
/opt/gitlab/embedded/bin/bundle:23:in `load'
/opt/gitlab/embedded/bin/bundle:23:in `<main>'
Tasks: TOP => gitlab:backup:create
(See full trace by running task with --trace)

What is the expected correct behavior?

• Have the log indicate ...failed Or ...SKIPPED when the rake task throws an error for an unsuccessful upload to remote storage.

2022-09-14 14:02:55 +0000 -- Uploading backup archive to remote storage REDACTED ... failed

Relevant logs and/or screenshots

Output of checks

Results of GitLab environment info

Expand for output related to GitLab environment info

(For installations with omnibus-gitlab package run and paste the output of:
`sudo gitlab-rake gitlab:env:info`)

(For installations from source run and paste the output of:
`sudo -u git -H bundle exec rake gitlab:env:info RAILS_ENV=production`)

Results of GitLab application Check

Expand for output related to the GitLab application check

(For installations with omnibus-gitlab package run and paste the output of:
sudo gitlab-rake gitlab:check SANITIZE=true)
(For installations from source run and paste the output of:
sudo -u git -H bundle exec rake gitlab:check RAILS_ENV=production SANITIZE=true)
(we will only investigate if the tests are passing)

Possible fixes

The backup gets stuck at https://gitlab.com/gitlab-org/gitlab/-/blob/v14.10.5-ee/lib/backup/manager.rb#L279

      puts_time "Uploading backup archive to remote storage #{remote_directory} ... ".color(:blue)
...

The check ought to get to #L291

 if upload
        if upload.respond_to?(:encryption) && upload.encryption
          puts_time "Uploading backup archive to remote storage #{remote_directory} ... ".color(:blue) + "done (encrypted with #{upload.encryption})".color(:green)
        else
          puts_time "Uploading backup archive to remote storage #{remote_directory} ... ".color(:blue) + "done".color(:green)
        end
      else
        puts_time "Uploading backup to #{remote_directory} failed".color(:red)
        raise Backup::Error, 'Backup failed'
      end
    end

The most likely fix lies in ensuring the log for a failed remote storage gets to #L291 for correct logging

added customer devopssystems groupgeo typebug labels

assigned to @bnyaringita

added sectioncore platform label

This was noted while debugging two internal customer tickets:

1. Premium customer using GCS for backups storage
2. Premium customer using AWS specific storage

@katrinleinweber Please help review.

Thank you, @bnyaringita for reporting this issue Do I understand correctly that (in the above example) ArgumentError: Missing required arguments… is only printed to the console, but should be logged to backup_json.log along with the stacktrace?

Yes, but the inital missing log is at least indicating "Uploading backup archive to remote storage my-test-storage ...failed" for a failed backup.

Then the ArgumentError: Missing required arguments… can also be added after that.

Hi @bnyaringita and @katrinleinweber, is this still being worked on? The Premium customer using GCS for backups storage from above is pushing for an update here.

@pzapf I see it has been scheduled below, so I believe it will be worked on, but no timeline yet.

I'd let @vsizov to help update on timelines once it is set.

mentioned in issue #374067

cc @sranasinghe @juan-silva

added priority2 label

Assigning severity3. Let me know if there are some objections.

added severity3 label

added workflowscheduling label

Assigning priority3 and workflowplanning breakdown

changed milestone to %15.8

added priority3 workflowplanning breakdown + 1 deleted label and removed priority2 workflowscheduling labels

added bugfunctional label

mentioned in issue gitlab-org/geo-team/discussions#5052 (closed)

mentioned in issue gitlab-org/geo-team/discussions#5055 (closed)

changed milestone to %15.9

mentioned in issue gitlab-org/geo-team/discussions#5058 (closed)

changed milestone to %15.11

added missed:15.9 label

removed milestone

added vintage label

added SLOMissed label

mentioned in issue #411497 (closed)

changed the description

set weight to 4

Since the unified backup refactors, the remote upload part, which is the one affected here now lives in:

https://gitlab.com/gitlab-org/gitlab/-/blob/99b08ac9f1fe7791806684a2177b4ea3e6503a71/lib/backup/remote_storage.rb

From this stacktrace:

ArgumentError: Missing required arguments: aws_access_key_id, aws_secret_access_key
/opt/gitlab/embedded/service/gitlab-rails/lib/backup/manager.rb:520:in `connect_to_remote_directory'
/opt/gitlab/embedded/service/gitlab-rails/lib/backup/manager.rb:323:in `upload'
/opt/gitlab/embedded/service/gitlab-rails/lib/backup/manager.rb:222:in `run_all_create_tasks'
/opt/gitlab/embedded/service/gitlab-rails/lib/backup/manager.rb:46:in `create'
/opt/gitlab/embedded/service/gitlab-rails/lib/tasks/gitlab/backup.rake:12:in `block (3 levels) in <top (required)>'

It seems the method in the refactored codebase that is throwing ArgumentError is : https://gitlab.com/gitlab-org/gitlab/-/blob/99b08ac9f1fe7791806684a2177b4ea3e6503a71/lib/backup/remote_storage.rb#L106-117

The location where the error is being handled is likely here:

https://gitlab.com/gitlab-org/gitlab/-/blob/99b08ac9f1fe7791806684a2177b4ea3e6503a71/lib/tasks/gitlab/backup.rake#L67-74:

        begin
          yield
        ensure
          backup_progress.puts(
            "#{Time.current} " + '-- Deleting backup and restore PID file ... '.color(:blue) + 'done'.color(:green)
          )
          File.delete(PID_FILE)
        end

We may want to consider having a similar catch all block either at the upload method or at something like create.

We should as well change to properly return a non zero status code (exit 1) so we can communicate that the backup action failed

mentioned in issue gitlab-com/support/support-team-meta#6439

added groupdurability label and removed groupgeo label