Restore fails with timeout (restic)

[dk-do]

What steps did you take and what happened:
Restore fails with:

time="2020-09-25T13:18:45Z" level=info msg="error restoring cert-manager-webhook: MutatingWebhookConfiguration.admissionregistration.k8s.io \"cert-manager-webhook\" is invalid: webhooks[0].sideEffects: Unsupported value: \"Unknown\": supported values: \"None\", \"NoneOnDryRun\"" logSource="pkg/restore/restore.go:1152" restore=velero/2nd-try
time="2020-09-25T17:16:23Z" level=error msg="unable to successfully complete restic restores of pod's volumes" error="timed out waiting for all PodVolumeRestores to complete" logSource="pkg/restore/restore.go:1244" restore=velero/2nd-try
time="2020-09-25T17:16:23Z" level=error msg="unable to successfully complete restic restores of pod's volumes" error="timed out waiting for all PodVolumeRestores to complete" logSource="pkg/restore/restore.go:1244" restore=velero/2nd-try

How did we start the restore?
We deleted all PVs for PostgreSQL (acid-postgres-0, acid-postgres-1, acid-postgres-2) . While PV 1 and 2 was successfully restored, PV 0 failed.

In addition we realized, that the lag of the two successful restored PVs was very high:

+-----------------------+-------------------------+-------------+------+---------+----+-----------+
|        Cluster        |          Member         |     Host    | Role |  State  | TL | Lag in MB |
+-----------------------+-------------------------+-------------+------+---------+----+-----------+
| acid-postgres-cluster | acid-postgres-cluster-0 | 10.244.3.64 |      | stopped |    |   unknown |
| acid-postgres-cluster | acid-postgres-cluster-1 | 10.244.5.69 |      | running |  7 |      1925 |
| acid-postgres-cluster | acid-postgres-cluster-2 | 10.244.7.90 |      | running |  7 |      1925 |
+-----------------------+-------------------------+-------------+------+---------+----+-----------+

The backup was taken with a lag of 0 MB.

What did you expect to happen:

Clean restore of all PVs.

The output of the following commands will help us better understand what's going on:
(Pasting long output into a GitHub gist or other pastebin is fine.)

• kubectl logs deployment/velero -n velero
• velero backup describe <backupname> or kubectl get backup/<backupname> -n velero -o yaml
• velero backup logs <backupname>
• velero restore describe <restorename> or kubectl get restore/<restorename> -n velero -o yaml
• velero restore logs <restorename>

All infos can be found here:

https://gist.github.com/dk-do/b894f15b22991536c24d4dcb953c81e4

Environment:

• Velero version (use velero version):

Client:
        Version: v1.5.1
        Git commit: 87d86a45a6ca66c6c942c7c7f08352e26809426c
Server:
        Version: v1.5.1

• Velero features (use velero client config get features):
  features: <NOT SET>

• Kubernetes version (use kubectl version):

Client Version: version.Info{Major:"1", Minor:"18", GitVersion:"v1.18.3", GitCommit:"2e7996e3e2712684bc73f0dec0200d64eec7fe40", GitTreeState:"clean", BuildDate:"2020-05-20T12:52:00Z", GoVersion:"go1.13.9", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"18", GitVersion:"v1.18.9", GitCommit:"94f372e501c973a7fa9eb40ec9ebd2fe7ca69848", GitTreeState:"clean", BuildDate:"2020-09-16T13:47:43Z", GoVersion:"go1.13.15", Compiler:"gc", Platform:"linux/amd64"}

• Kubernetes installer & version:

none

• Cloud provider or hardware configuration:
  none - bare metal

• OS (e.g. from /etc/os-release):

NAME="Ubuntu"
VERSION="18.04.5 LTS (Bionic Beaver)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 18.04.5 LTS"
VERSION_ID="18.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=bionic
UBUNTU_CODENAME=bionic

Vote on this issue!

This is an invitation to the Velero community to vote on issues, you can see the project's top voted issues listed here.
Use the "reaction smiley face" up to the right of this comment to vote.

• 👍 for "I would like to see this bug fixed as soon as possible"
• 👎 for "There are more important bugs to focus on right now"

[dk-do]

Anybody an idea?

[cedricve]

I have the same error, tried to take a backup on a GCP account and moved it to another GCP account. Some PV's where moved, however some werent. After 4 hours the restore timedout.

time="2020-11-29T14:41:03Z" level=info msg="Attempting to restore VolumeSnapshotLocation: default" logSource="pkg/restore/restore.go:1107" restore=velero/29-11-2020-restore
time="2020-11-29T14:41:03Z" level=info msg="Restore of VolumeSnapshotLocation, default skipped: it already exists in the cluster and is the same as the backed up version" logSource="pkg/restore/restore.go:1164" restore=velero/29-11-2020-restore
time="2020-11-29T14:41:03Z" level=info msg="Waiting for all restic restores to complete" logSource="pkg/restore/restore.go:488" restore=velero/29-11-2020-restore
time="2020-11-29T18:40:19Z" level=error msg="unable to successfully complete restic restores of pod's volumes" error="timed out waiting for all PodVolumeRestores to complete" logSource="pkg/restore/restore.go:1296" restore=velero/29-11-2020-restore
time="2020-11-29T18:40:19Z" level=error msg="unable to successfully complete restic restores of pod's volumes" error="timed out waiting for all PodVolumeRestores to complete" logSource="pkg/restore/restore.go:1296" restore=velero/29-11-2020-restore
time="2020-11-29T18:40:19Z" level=error msg="unable to successfully complete restic restores of pod's volumes" error="timed out waiting for all PodVolumeRestores to complete" logSource="pkg/restore/restore.go:1296" restore=velero/29-11-2020-restore
time="2020-11-29T18:40:19Z" level=error msg="unable to successfully complete restic restores of pod's volumes" error="timed out waiting for all PodVolumeRestores to complete" logSource="pkg/restore/restore.go:1296" restore=velero/29-11-2020-restore
time="2020-11-29T18:40:19Z" level=error msg="unable to successfully complete restic restores of pod's volumes" error="timed out waiting for all PodVolumeRestores to complete" logSource="pkg/restore/restore.go:1296" restore=velero/29-11-2020-restore
time="2020-11-29T18:40:19Z" level=info msg="Done waiting for all restic restores to complete" logSource="pkg/restore/restore.go:504" restore=velero/29-11-2020-restore
time="2020-11-29T18:40:19Z" level=info msg="Waiting for all post-restore-exec hooks to complete" logSource="pkg/restore/restore.go:508" restore=velero/29-11-2020-restore
time="2020-11-29T18:40:19Z" level=info msg="Done waiting for all post-restore exec hooks to complete" logSource="pkg/restore/restore.go:516" restore=velero/29-11-2020-restore
time="2020-11-29T18:40:20Z" level=info msg="restore completed" logSource="pkg/controller/restore_controller.go:482" restore=velero/29-11-2020-restore

[dsu-igeek]

I'd like to understand what's going on a little better.

It sounds like you had a cluster, backed it up, then deleted the PVs and attempted to restore them. We would recommend that you simply restore the whole cluster.

What generated the table that you included with "Lag in MB" ?

[dk-do]

We backed up a PostgreSQL Cluster which consists auf 3 PVs because the cluster has 3 replicas (each replica has its own PV).
Then we deleted the three PVs and restored them.

The table with "Lag in MB" shows the current cluster status. The value means, that they are x-MB behind the leader. But this may happen because cluster member "acid-cluster-0" is not running and no leader was elected.

A "normal" cluster status is:

+-----------------------+-------------------------+--------------+--------+---------+----+-----------+
|        Cluster        |          Member         |     Host     |  Role  |  State  | TL | Lag in MB |
+-----------------------+-------------------------+--------------+--------+---------+----+-----------+
| acid-postgres-cluster | acid-postgres-cluster-0 | 10.244.3.185 |        | running | 12 |         0 |
| acid-postgres-cluster | acid-postgres-cluster-1 | 10.244.2.49  |        | running | 12 |         0 |
| acid-postgres-cluster | acid-postgres-cluster-2 | 10.244.1.223 | Leader | running | 12 |           |
+-----------------------+-------------------------+--------------+--------+---------+----+-----------+

This table shows that one cluster member was elected as a leader and the other ones are following. The "Lag in MB" is 0 because all replicas are in sync.

[dsu-igeek]

What is generating that cluster status? That's not a standard Kubernetes output. Is that Postgres output or something else?

In general, deleting the PVs and then restoring them is not the recommended way to use Velero. Doing a Velero restore and re-installing the Kubernetes resources allows everything to be ordered properly and PVs to be attached.