Backups fail on restored machine

[adamspn]

Hi all,

I have Veeam Agent for Linux freshly installed for a test. I made a new VM in ESXi, put a webpage on it, and installed VAL from the repo as prescribed in the documentation.

I then set up an encrypted backup job to an SMB share on a QNAP on the subnet and successfully backed up to it.

I then down that VM, created a new VM, and using the restore media image restored the backup to the new machine. Tested the webpage: perfect.

Problem

The backups on this restored VM are failing. If I open veeam

Code: Select all

sudo veeam

I see my backup job 'BackupJob' listed as failed. In the details:

Code: Select all

Time        Action                                                          Duration
12:35:35    Job BackupJob start at 2018-01-31 12:35:35 UTC
12:35:36    Preparing to backup
12:35:36    Creating volume snapshot                                        00:00:00
13:29:34    [error] Job failed unexpectedly

Those 12:35 times are the times at which I started the successful backup job. It took only a few minutes, but almost an hour later it has reported failed, even though the UI reported it succeeded.

If I attempt to run the job again (S) from the menu, it fails with these details:

Code: Select all

Time          Action                                                        Duration
13:58:13    Job BackupJob start at 2018-01-31 13:58:13 UTC
13:58:14    [error] Failed to perform backup
13:58:14    [error] Unable to decrypt password for qnap/serverbackups...
13:58:14    [error] Failed to check repository Repository_1 {254dd180-4...
13:58:14    [error] Processing finished with errors at 2018-08-31 13:58...

I've had a search on here and on the Web for some of the phrases from that log, but found nothing.

What's going wrong here?

Regards,

Adam

[adamspn]

Here's the Job.log

Code: Select all

[31.08.2018 13:58:13] <139628941967104> cli    | Initializing new log filter.
[31.08.2018 13:58:13] <139628941967104>        | ====================================================================================
[31.08.2018 13:58:13] <139628941967104> lpb    | {
[31.08.2018 13:58:13] <139628941967104> lpb    |   Veeam Agent for Linux: veeamjobman.
[31.08.2018 13:58:13] <139628941967104> lpb    |   Version: 2.0.1.665
[31.08.2018 13:58:13] <139628941967104> lpb    |   PID: 2748
[31.08.2018 13:58:13] <139628941967104> lpb    |   uname
[31.08.2018 13:58:13] <139628941967104> lpb    |     sysname : Linux
[31.08.2018 13:58:13] <139628941967104> lpb    |     release : 4.15.0-33-generic
[31.08.2018 13:58:13] <139628941967104> lpb    |     version : #36-Ubuntu SMP Wed Aug 15 16:00:05 UTC 2018
[31.08.2018 13:58:13] <139628941967104> lpb    |     machine : x86_64
[31.08.2018 13:58:13] <139628941967104> lpb    | }
[31.08.2018 13:58:13] <139628941967104> lpbman | Main thread has started.
[31.08.2018 13:58:13] <139628941967104> lpbcore| Connecting to veeamservice...
[31.08.2018 13:58:13] <139628941967104>        |   Closing socket device.
[31.08.2018 13:58:13] <139628941967104> lpbcore| Connecting to veeamservice... ok.
[31.08.2018 13:58:13] <139628941967104> lpbcore| No license installed.
[31.08.2018 13:58:13] <139628941967104> lpbcore| LpbManSession: Processing commands.
[31.08.2018 13:58:13] <139628941967104> lpbcore|   Sending PID: [2748].
[31.08.2018 13:58:13] <139628941967104> lpbcore|   Sending Session UUID: [{b7a3364e-7386-4f0f-8111-32d1b28ae0aa}].
[31.08.2018 13:58:13] <139628941967104> lpbcore|   Waiting for a command.
[31.08.2018 13:58:13] <139628941967104> lpbcore|   LpbManSession: Starting backup job.
[31.08.2018 13:58:13] <139628941967104> lpbcore|     Job UUID: [{895bc0f0-7d08-4d51-b326-6f8fe3589b7d}] (normal priority).
[31.08.2018 13:58:13] <139628941967104> lpbcore|     Is active full? [false].
[31.08.2018 13:58:13] <139628941967104> lpbcore|     System information:
[31.08.2018 13:58:13] <139628941967104> lpbcore|       Running [lsb_release -a].
[31.08.2018 13:58:13] <139628941967104> lpbcore|         Distributor ID:Ubuntu
[31.08.2018 13:58:13] <139628941967104> lpbcore|         Description:Ubuntu 18.04.1 LTS
[31.08.2018 13:58:13] <139628941967104> lpbcore|         Release:18.04
[31.08.2018 13:58:13] <139628941967104> lpbcore|         Codename:bionic
[31.08.2018 13:58:13] <139628941967104> lpbcore|       Running [cat /etc/*release].
[31.08.2018 13:58:13] <139628941967104> lpbcore|         DISTRIB_ID=Ubuntu
[31.08.2018 13:58:13] <139628941967104> lpbcore|         DISTRIB_RELEASE=18.04
[31.08.2018 13:58:13] <139628941967104> lpbcore|         DISTRIB_CODENAME=bionic
[31.08.2018 13:58:13] <139628941967104> lpbcore|         DISTRIB_DESCRIPTION="Ubuntu 18.04.1 LTS"
[31.08.2018 13:58:13] <139628941967104> lpbcore|         NAME="Ubuntu"
[31.08.2018 13:58:13] <139628941967104> lpbcore|         VERSION="18.04.1 LTS (Bionic Beaver)"
[31.08.2018 13:58:13] <139628941967104> lpbcore|         ID=ubuntu
[31.08.2018 13:58:13] <139628941967104> lpbcore|         ID_LIKE=debian
[31.08.2018 13:58:13] <139628941967104> lpbcore|         PRETTY_NAME="Ubuntu 18.04.1 LTS"
[31.08.2018 13:58:13] <139628941967104> lpbcore|         VERSION_ID="18.04"
[31.08.2018 13:58:13] <139628941967104> lpbcore|         HOME_URL="https://www.ubuntu.com/"
[31.08.2018 13:58:13] <139628941967104> lpbcore|         SUPPORT_URL="https://help.ubuntu.com/"
[31.08.2018 13:58:13] <139628941967104> lpbcore|         BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
[31.08.2018 13:58:13] <139628941967104> lpbcore|         PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
[31.08.2018 13:58:13] <139628941967104> lpbcore|         VERSION_CODENAME=bionic
[31.08.2018 13:58:13] <139628941967104> lpbcore|         UBUNTU_CODENAME=bionic
[31.08.2018 13:58:13] <139628941967104> lpbcore|       Running [lsblk].
[31.08.2018 13:58:13] <139628941967104> lpbcore|         NAME   MAJ:MIN RM  SIZE RO TYPE MOUNTPOINT
[31.08.2018 13:58:13] <139628941967104> lpbcore|         loop0    7:0    0 86.6M  1 loop /snap/core/4486
[31.08.2018 13:58:13] <139628941967104> lpbcore|         loop1    7:1    0 87.9M  1 loop /snap/core/5328
[31.08.2018 13:58:13] <139628941967104> lpbcore|         sda      8:0    0   20G  0 disk 
[31.08.2018 13:58:13] <139628941967104> lpbcore|         ├─sda1   8:1    0    1M  0 part 
[31.08.2018 13:58:13] <139628941967104> lpbcore|         └─sda2   8:2    0   20G  0 part /
[31.08.2018 13:58:13] <139628941967104> lpbcore|         sr0     11:0    1   98M  0 rom  
[31.08.2018 13:58:13] <139628941967104> lpbcore|   LpbManSession: Starting backup job. ok.
[31.08.2018 13:58:13] <139628898694912>        | Thread started. Thread id: 139628898694912, parent id: 139628941967104, role: Volume backup job execution
[31.08.2018 13:58:13] <139628898694912> lpbcore| BackupJobPerformer: Creating backup.
[31.08.2018 13:58:13] <139628898694912> lpbcore| WARN|Method invocation was not finalized. Method id [1]. Class: [lpbcorelib::interaction::IServiceCryptoManager]
[31.08.2018 13:58:13] <139628898694912> lpbcore| ERR |Failed to decrypt buffer.
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |--tr:Failed to execute method [1] for class [lpbcorelib::interaction::proxystub::CServiceCryptoManagerStub].
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |--tr:Failed to invoke method [1] in class [lpbcorelib::interaction::IServiceCryptoManager].
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |An exception was thrown from thread [139628898694912].
[31.08.2018 13:58:13] <139628898694912> lpbcore| ERR |Failed to decrypt buffer.
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |--tr:Failed to execute method [1] for class [lpbcorelib::interaction::proxystub::CServiceCryptoManagerStub].
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |Unable to decrypt buffer.
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |Unable to decrypt password.
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |An exception was thrown from thread [139628898694912].
[31.08.2018 13:58:13] <139628898694912> lpbcore| WARN|Method invocation was not finalized. Method id [1]. Class: [lpbcorelib::interaction::IServiceCryptoManager]
[31.08.2018 13:58:13] <139628898694912> lpbcore| ERR |Failed to decrypt buffer.
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |--tr:Failed to execute method [1] for class [lpbcorelib::interaction::proxystub::CServiceCryptoManagerStub].
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |--tr:Failed to invoke method [1] in class [lpbcorelib::interaction::IServiceCryptoManager].
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |An exception was thrown from thread [139628898694912].
[31.08.2018 13:58:13] <139628898694912> lpbcore| ERR |Failed to decrypt buffer.
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |--tr:Failed to execute method [1] for class [lpbcorelib::interaction::proxystub::CServiceCryptoManagerStub].
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |Unable to decrypt buffer.
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |Unable to decrypt password.
[31.08.2018 13:58:13] <139628898694912> lpbcore| >>  |An exception was thrown from thread [139628898694912].
[31.08.2018 13:58:14] <139628898694912> lpbcore| BackupJobPerformer: Creating backup. Failed.
[31.08.2018 13:58:14] <139628898694912> vmb    | [SessionLog][error] Failed to perform backup.
[31.08.2018 13:58:14] <139628898694912> vmb    | [SessionLog][error] Unable to decrypt password for qnap1/serverbackupsLinux. Please run job wizard.
[31.08.2018 13:58:14] <139628898694912> vmb    | [SessionLog][error] Failed to check repository Repository_1 {254dd180-4777-4241-8f7d-e9fa952c3cd0}.
[31.08.2018 13:58:14] <139628898694912> vmb    | [SessionLog][error] Processing finished with errors at 2018-08-31 13:58:14 UTC.
[31.08.2018 13:58:14] <139628898694912> lpbcore| ERR |Unable to decrypt password for qnap1/serverbackupsLinux. Please run job wizard.
[31.08.2018 13:58:14] <139628898694912> lpbcore| >>  |Failed to check repository Repository_1 {254dd180-4777-4241-8f7d-e9fa952c3cd0}.
[31.08.2018 13:58:14] <139628898694912> lpbcore| >>  |--tr:Failed to prepare destination/repository.
[31.08.2018 13:58:14] <139628898694912> lpbcore| >>  |Backup job has failed.
[31.08.2018 13:58:14] <139628898694912> lpbcore| >>  |An exception was thrown from thread [139628898694912].
[31.08.2018 13:58:14] <139628941967104>        |   Closing socket device.
[31.08.2018 13:58:14] <139628941967104> lpbcore| LpbManSession: Processing commands. ok.
[31.08.2018 13:58:14] <139628941967104>        | Closing socket device.
[31.08.2018 13:58:14] <139628898694912> lpbcore| JOB STATUS: FAILED.
[31.08.2018 13:58:14] <139628898694912>        | Thread finished. Role: 'Volume backup job execution'.
[31.08.2018 13:58:14] <139628941967104>        | Closing socket device.
[31.08.2018 13:58:14] <139628941967104>        | Closing socket device.
[31.08.2018 13:58:14] <139628941967104> lpbman | Application session has been finished.

[PTide]

Hi,

It took only a few minutes, but almost an hour later it has reported failed, even though the UI reported it succeeded.

That alone is the valid reason to contact support team directly since such behaviour is incorrect.

Also, have you tried to specify the same encryption password in the wizard again? It seems that the new machine does not know your encryption key.

Thanks

[adamspn]

Hi PTide,

Thanks for your reply. I submitted a support ticket a couple of hours after posting here.

I have run the wizard again, but to no avail.

When I run (C) Configure, the page about the destination of the backup has 'Local' selected instead of remote file share.

When I get to the Encryption page, Encryption is disabled. Enabling it gives me the message "Changing encryption settings will force an Active Full backup during the next job run." -- it is as though encryption is no longer configured.

So I specify the password and then run the job and it fails in the exact same way.

[PTide]

Would you post your case ID for reference, please?

Meanwhile I'm waiting for QA's answer, will update the thread once I get some info.

Thanks

[adamspn]

Sure thing. My case ID is # 03172764

[PTide]

Sorry for my long abscence. Here is the state:

That's a bug. After you had restored to another machine and had walked through the wizard again it should have let you proceed with a full backup. Please note, that by design the Agent will start full backup after you restore from encrypted backup to another machine.

Thank you for bringing this up!

[adamspn]

Thanks.

To clarify, when you say 'full backup' do you mean the start of a new chain, where 'full' is the base image against which the subsequent chain of incrementals would be made?

In that case, do you mean that when I restore a machine I'm not supposed to be able to continue the chain, i.e. the restored machine should start a new chain, but the bug means that it is trying to continue the chain without having the encryption key?

Or do you mean that the bug is the backup chain failing to continue the chain?

[PTide]

I mean that the product is not supposed to create incremental backup in case you have restored the encrypted backup to another machine. In this case the chain is supposed to be continued with a full backup after you go through the wizard again.

Thanks

[adamspn]

So we have two bugs:

1) Restoring from encrypted backup to another machine should start a full backup, but that failed.

2) Walking through the wizard again should fix #1, but didn't.

Is that right?

[PTide]

Not exactly. 1 is by design, 2 is a bug. After restoration from an encrypted backup you should be able to continue with full backup, provided that you have gone through the wizard again.

Thanks

[adamspn]

Got it, thanks for the clarification.