Suddenly cannot backup Exhange VM (vsphere 6.0)

Hi Bill,

In your case the process fails on quiesced snapshot creation (quiesced=on, memory=off) which should also fail if you run it from vSphere client. Probably VMware Tools need to be updated within this VM to fix the problem - if not then analyzing the Windows Event logs should give more clues.

Also note the following: we're now in progress of preparation of an update (to be released within the next couple of weeks, i.e. ASAP) for Acronis Backup for VMware 9 with vSphere 6 support and while backup of VMs running on vSphere 6 works with the current (10007) build we know that VM recovery won't work onto ESXi 6 hosts as well as "ESXi host configuration backup" or "Run VM from Backup" functionality. In other words update is required to include full support for vSphere 6.

Thank you.
--
Best regards,
Vasily
Acronis Virtualization Program Manager

I got the snapshot issue worked out by disabling app quescing but now get this:
Backup has failed. Please check the log for additional information.
1 Information 3/18/2015 11:04:38 AM Task 'Back up Exchange' was changed.
2 Information 3/18/2015 11:04:38 AM Task 'Back up Exchange' changed its state from 'idle' to 'running'.
3 Information 3/18/2015 11:04:38 AM Task 'Back up Exchange' was started.
4 Information 3/18/2015 11:04:38 AM Backing up VM(s).
5 Information 3/18/2015 11:04:38 AM Successfully connected to 'VMware vCenter Server 6.0.0 build-2559267'.
6 Information 3/18/2015 11:04:38 AM Successfully connected to 'VMware ESXi 6.0.0 build-2494585' through VMware vCenter Server.
7 Information 3/18/2015 11:04:39 AM Successfully connected to 'VMware ESXi 6.0.0 build-2494585' through VMware vCenter Server.
8 Information 3/18/2015 11:04:39 AM Successfully connected to 'VMware ESXi 6.0.0 build-2494585' through VMware vCenter Server.
9 Information 3/18/2015 11:04:40 AM Successfully connected to 'VMware ESXi 6.0.0 build-2494585' through VMware vCenter Server.
10 Information 3/18/2015 11:04:41 AM Successfully connected to 'VMware vCenter Server 6.0.0 build-2559267'.
11 Information 3/18/2015 11:04:41 AM Successfully connected to 'VMware vCenter Server 6.0.0 build-2559267'.
12 Information 3/18/2015 11:04:41 AM Successfully connected to 'VMware ESXi 6.0.0 build-2494585' through VMware vCenter Server.
13 Information 3/18/2015 11:06:54 AM Meta collection started for application: Microsoft Exchange Server
14 Information 3/18/2015 11:08:08 AM Collected meta backup started for application: Microsoft Exchange Server
15 Information 3/18/2015 11:08:23 AM Creating snapshot (3/18/2015 11:08:11 AM).
16 Information 3/18/2015 11:08:23 AM Loading virtual machine 'vm://ED58B306-62ED-440D-929D-9BD08623CB2C/502419ab-666b-6c0c-8686-2e2be1e3d985?host=host-65&type=vmwesx' into the disk subsystem.
17 Information 3/18/2015 11:08:24 AM VMware_VDDK: SSLVerifyIsEnabled: failed to open the product registry key. Falling back to default behavior: verification off. LastError = 0
18 Information 3/18/2015 11:08:24 AM VMware_VDDK: SSLVerifyIsEnabled: failed to open the product registry key. Falling back to default behavior: verification off. LastError = -2146885628
19 Information 3/18/2015 11:08:24 AM VMware_VDDK: SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error
20 Information 3/18/2015 11:08:24 AM VMware_VDDK: SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error
21 Information 3/18/2015 11:08:27 AM VMware_VDDK: SSLVerifyIsEnabled: failed to open the product registry key. Falling back to default behavior: verification off. LastError = -2146885628
22 Information 3/18/2015 11:08:27 AM VMware_VDDK: SSLVerifyIsEnabled: failed to open the product registry key. Falling back to default behavior: verification off. LastError = 0
23 Information 3/18/2015 11:08:27 AM VMware_VDDK: SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error
24 Information 3/18/2015 11:08:27 AM VMware_VDDK: SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error
25 Information 3/18/2015 11:08:29 AM VMware_VDDK: SSLVerifyIsEnabled: failed to open the product registry key. Falling back to default behavior: verification off. LastError = -2146885628
26 Information 3/18/2015 11:08:29 AM VMware_VDDK: SSLVerifyIsEnabled: failed to open the product registry key. Falling back to default behavior: verification off. LastError = 0
27 Information 3/18/2015 11:08:29 AM VMware_VDDK: SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error
28 Information 3/18/2015 11:08:29 AM VMware_VDDK: SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error
29 Information 3/18/2015 11:08:31 AM VMware_VDDK: SSLVerifyIsEnabled: failed to open the product registry key. Falling back to default behavior: verification off. LastError = -2146885628
30 Information 3/18/2015 11:08:31 AM VMware_VDDK: SSLVerifyIsEnabled: failed to open the product registry key. Falling back to default behavior: verification off. LastError = 0
31 Information 3/18/2015 11:08:31 AM VMware_VDDK: SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error
32 Information 3/18/2015 11:08:31 AM VMware_VDDK: SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error
33 Information 3/18/2015 11:08:33 AM Analyzing partition 'C:'...
34 Information 3/18/2015 11:08:33 AM Analyzing partition 'D:'...
35 Information 3/18/2015 11:08:34 AM Analyzing partition 'E:'...
36 Information 3/18/2015 11:08:34 AM Analyzing partition 'F:'...
37 Information 3/18/2015 11:08:34 AM Analyzing partition 'G:'...
38 Warning 3/18/2015 11:08:37 AM Applications quiescing using VMware VSS components has failed. Application data inside the backup might be inconsistent since the snapshot was taken without VSS. Internal error: VSS Writer with id: Microsoft Exchange Server VSS Writer not found
Additional info:
--------------------
Error code: 1
Module: 560
LineInfo: c0d34cead0ce9e15
Fields:
Message: Applications quiescing using VMware VSS components has failed. Application data inside the backup might be inconsistent since the snapshot was taken without VSS. Internal error: VSS Writer with id: Microsoft Exchange Server VSS Writer not found
--------------------
39 Information 3/18/2015 11:09:01 AM Preparing for the Microsoft Exchange database validation.
40 Error 3/18/2015 11:09:01 AM The operation has failed.
Additional info:
--------------------
Error code: 26
Module: 100
LineInfo: 48afbd3608a410ca
Fields:
Message: The operation has failed.
--------------------
Error code: 368
Module: 149
LineInfo: 4db9605401c1520d
Fields:
Message: Failed to prepare for the Microsoft Exchange database validation.
--------------------
Error code: 358
Module: 149
LineInfo: 4db9605401c150b8
Fields: $module : C:\Program Files (x86)\Common Files\Acronis\vmProtectAgent\vmProtectService.exe
Message: VSS metadata is missing or corrupt.
--------------------
Error code: 1001
Module: 460
LineInfo: df98e120ab10cc6b
Fields:
Message: Failed to parse MsExchange VSS writer metadata.
--------------------
Error code: 1003
Module: 460
LineInfo: df98e120ab10cc53
Fields:
Message: Expected XML tag not found: WRITER_COMPONENTS
--------------------
41 Warning 3/18/2015 11:09:13 AM Failed to execute backup agent command --backup-finished
Additional info:
--------------------
Error code: 3
Module: 548
LineInfo: d15400b5b8e120a9
Fields:
Message: Failed to execute backup agent command --backup-finished
--------------------
Error code: 1
Module: 470
LineInfo: dd1e7a681d3fe6b4
Fields: $module : C:\Users\ADMINI~1.TR\AppData\Local\Temp\1B0F1F45-F0D2-45F2-9FA0-0563B4B9ECA6\exchange_backup_agent.exe
Message: Failed to process command 'Log Truncation'.
--------------------
Error code: 300
Module: 470
LineInfo: fc0971706d90faa0
Fields: $module : C:\Users\ADMINI~1.TR\AppData\Local\Temp\1B0F1F45-F0D2-45F2-9FA0-0563B4B9ECA6\exchange_backup_agent.exe
Message: Failed to send the backup result to the VSS service.
--------------------
Error code: 65520
Module: 0
LineInfo: bd28fdbd64edb8bf
Fields: code : 2147942402
Message: The system cannot find the file specified
--------------------
42 Information 3/18/2015 11:09:13 AM Remove snapshot (snapshot-226).
43 Information 3/18/2015 11:09:16 AM Task 'Back up Exchange' changed its state from 'running' to 'idle'.
44 Error 3/18/2015 11:09:16 AM Task 'Back up Exchange' failed: 'Failed to create a backup.
Additional info:
--------------------
Error code: 3
Module: 435
LineInfo: 555b5abba095034c
Fields: $module : C:\Program Files (x86)\Acronis\vmProtect\Windows Agent\vmms.exe
Message: Failed to create a backup.
--------------------
Error code: 32786
Module: 114
LineInfo: 28314c961de7d337
Fields:
Message: Failed to prepare for backing up.
--------------------
Error code: 353
Module: 149
LineInfo: a71592046cb2c5f6
Fields:
Message: Failed to back up the group.
--------------------
Error code: 2
Module: 218
LineInfo: cd07f9d978d3a2a3
Fields:
Message: Error occurred while running the backup and recovery engine.
--------------------
Error code: 368
Module: 149
LineInfo: 4db9605401c1520d
Fields: $module : C:\Program Files (x86)\Common Files\Acronis\vmProtectAgent\vmProtectService.exe
Message: Failed to prepare for the Microsoft Exchange database validation.
--------------------
Error code: 358
Module: 149
LineInfo: 4db9605401c150b8
Fields: $module : C:\Program Files (x86)\Common Files\Acronis\vmProtectAgent\vmProtectService.exe
Message: VSS metadata is missing or corrupt.
--------------------
Error code: 1001
Module: 460
LineInfo: df98e120ab10cc6b
Fields:
Message: Failed to parse MsExchange VSS writer metadata.
--------------------
Error code: 1003
Module: 460
LineInfo: df98e120ab10cc53
Fields:
Message: Expected XML tag not found: WRITER_COMPONENTS --------------------'.

Hi Bill,

Disabling quiescing means disabling VSS processing inside the VM and since application-aware backup (which you are using) is relying on VSS entirely (including log truncation part) - it is not supposed to work with quiescing disabled. You should investigate why quiescing doesn't work on the VM while it is enabled in VM properties.

Thank you.
--
Best regards,
Vasily
Acronis Virtualization Program Manager

I started a ticket with VMware, and they had me reinstall VMware tools without the VMware tools VSS driver. Snapshots work fine on the host, but not for VMProtect. The logs:
How can I get this to work?

Do I need to try it as a new job?

Backup has failed. Please check the log for additional information.
1 Information 3/19/2015 5:04:09 PM Task 'Back up Exchange' was changed.
2 Information 3/19/2015 5:04:09 PM Task 'Back up Exchange' changed its state from 'idle' to 'running'.
3 Information 3/19/2015 5:04:09 PM Task 'Back up Exchange' was started.
4 Information 3/19/2015 5:04:09 PM Backup deletion
5 Information 3/19/2015 5:04:14 PM 1 backup(s) have been deleted from archive Exchange.TIB.
6 Information 3/19/2015 5:04:14 PM Backup deletion has successfully completed.
7 Information 3/19/2015 5:04:14 PM Backing up VM(s).
8 Information 3/19/2015 5:04:14 PM Successfully connected to 'VMware vCenter Server 6.0.0 build-2559267'.
9 Information 3/19/2015 5:04:14 PM Successfully connected to 'VMware ESXi 6.0.0 build-2494585' through VMware vCenter Server.
10 Information 3/19/2015 5:04:15 PM Successfully connected to 'VMware ESXi 6.0.0 build-2494585' through VMware vCenter Server.
11 Information 3/19/2015 5:04:15 PM Successfully connected to 'VMware ESXi 6.0.0 build-2494585' through VMware vCenter Server.
12 Information 3/19/2015 5:04:15 PM Successfully connected to 'VMware ESXi 6.0.0 build-2494585' through VMware vCenter Server.
13 Information 3/19/2015 5:04:16 PM Successfully connected to 'VMware vCenter Server 6.0.0 build-2559267'.
14 Information 3/19/2015 5:04:17 PM Successfully connected to 'VMware vCenter Server 6.0.0 build-2559267'.
15 Information 3/19/2015 5:04:17 PM Successfully connected to 'VMware ESXi 6.0.0 build-2494585' through VMware vCenter Server.
16 Error 3/19/2015 5:06:09 PM The operation has failed.
Additional info:
--------------------
Error code: 26
Module: 100
LineInfo: 48afbd3608a410ca
Fields:
Message: The operation has failed.
--------------------
Error code: 537
Module: 149
LineInfo: fc2924f06484b5f1
Fields:
Message: Meta collection during application-aware backup failed.
--------------------
Error code: 3
Module: 548
LineInfo: d15400b5b8e120ed
Fields:
Message: Failed to execute backup agent command --check-env
--------------------
Error code: 1
Module: 470
LineInfo: dd1e7a681d3fe6b4
Fields: $module : C:\Users\ADMINI~1.TR\AppData\Local\Temp\0A99A13D-BB1A-4C3C-A126-D9448AD624C9\exchange_backup_agent.exe
Message: Failed to process command 'CheckEnvironment'.
--------------------
Error code: 25
Module: 470
LineInfo: 43403141c47105e7
Fields: $module : C:\Users\ADMINI~1.TR\AppData\Local\Temp\0A99A13D-BB1A-4C3C-A126-D9448AD624C9\exchange_backup_agent.exe
Message: The VSS components of VMware Tools are corrupted or not installed.
--------------------
17 Warning 3/19/2015 5:06:19 PM Failed to execute backup agent command --backup-finished
Additional info:
--------------------
Error code: 3
Module: 548
LineInfo: d15400b5b8e120a9
Fields:
Message: Failed to execute backup agent command --backup-finished
--------------------
Error code: 1
Module: 470
LineInfo: dd1e7a681d3fe6b4
Fields: $module : C:\Users\ADMINI~1.TR\AppData\Local\Temp\0A99A13D-BB1A-4C3C-A126-D9448AD624C9\exchange_backup_agent.exe
Message: Failed to process command 'Log Truncation'.
--------------------
Error code: 300
Module: 470
LineInfo: fc0971706d90faa0
Fields: $module : C:\Users\ADMINI~1.TR\AppData\Local\Temp\0A99A13D-BB1A-4C3C-A126-D9448AD624C9\exchange_backup_agent.exe
Message: Failed to send the backup result to the VSS service.
--------------------
Error code: 65520
Module: 0
LineInfo: bd28fdbd64edb8bf
Fields: code : 2147942402
Message: The system cannot find the file specified
--------------------
18 Information 3/19/2015 5:06:22 PM Task 'Back up Exchange' changed its state from 'running' to 'idle'.
19 Error 3/19/2015 5:06:22 PM Task 'Back up Exchange' failed: 'Failed to create a backup.
Additional info:
--------------------
Error code: 3
Module: 435
LineInfo: 555b5abba095034c
Fields: $module : C:\Program Files (x86)\Acronis\vmProtect\Windows Agent\vmms.exe
Message: Failed to create a backup.
--------------------
Error code: 32786
Module: 114
LineInfo: 28314c961de7d337
Fields:
Message: Failed to prepare for backing up.
--------------------
Error code: 353
Module: 149
LineInfo: a71592046cb2c5f6
Fields:
Message: Failed to back up the group.
--------------------
Error code: 2
Module: 218
LineInfo: cd07f9d978d3a2a3
Fields:
Message: Error occurred while running the backup and recovery engine.
--------------------
Error code: 537
Module: 149
LineInfo: fc2924f06484b5f1
Fields: $module : C:\Program Files (x86)\Common Files\Acronis\vmProtectAgent\vmProtectService.exe
Message: Meta collection during application-aware backup failed.
--------------------
Error code: 3
Module: 548
LineInfo: d15400b5b8e120ed
Fields:
Message: Failed to execute backup agent command --check-env
--------------------
Error code: 1
Module: 470
LineInfo: dd1e7a681d3fe6b4
Fields: $module : C:\Users\ADMINI~1.TR\AppData\Local\Temp\0A99A13D-BB1A-4C3C-A126-D9448AD624C9\exchange_backup_agent.exe
Message: Failed to process command 'CheckEnvironment'.
--------------------
Error code: 25
Module: 470
LineInfo: 43403141c47105e7
Fields: $module : C:\Users\ADMINI~1.TR\AppData\Local\Temp\0A99A13D-BB1A-4C3C-A126-D9448AD624C9\exchange_backup_agent.exe
Message: The VSS components of VMware Tools are corrupted or not installed.
--------------------'.

Hi Bill,

Well the error you see now is obvious: without VSS components snapshot from VMware won't be interacting with VSS and therefore databases inside the VM will be in crash-consistent state in the snapshot and therefore application-aware backup of such VM is impossible. Installing VMware Tools without VSS components is practically equal to disabling quiescing at all.

There are 2 options:

1) Make VMware Tools work with VSS components installed (to generate proper VSS snapshot and quiesce applications)
OR
2) Disable application-aware backup in the backup task options.

Thank you.
--
Best regards,
Vasily
Acronis Virtualization Program Manager

VMware was no help... all they said was that the VMWARE vss was conflicting in the VM and turned it off.

So how can I make VMware tools work with the VSS components installed???

Ok.. Found the issue. There is a bug in ESXI 6 with large Virtual machines or ones with the 100 meg service partition that Windows Server 2008 / 2012 puts in. The issue causes CBT on the host to run out of memory right after snapshot creation.
So to make app aware backups, I turned off CBT tracking in the guest VM. Backups take longer, but at least they get done.
I am waiting for a call back from VMware to show the bug and request a fix.

Hi Bill,

Thank you for the update! That's really an interesting finding. I never would've thought that CBT may cause VSS problems inside a VM. Please (if possible) update the thread when you get a confirmation from VMware and we will publish the details in our Knowledge Base.

Thank you.
--
Best regards,
Vasily
Acronis Virtualization Program Manager

Hey Guys,

I ran into the same issue after upgrading to 6.0; Snapshots fail due to CBT memory issue. It took vmware a week to acknowledge the bug does indeed exist in 6.0. They have provided no ETA on a hotfix or patch. As Bill mentioned, disabling cbt does resolve the issue. Vmware has yet to publish a Kb detailing the problem. If/when I see it, I'll gladly share here.

Josh, thank you for sharing the info!

Josh Warnke wrote:

Hey Guys,

I ran into the same issue after upgrading to 6.0; Snapshots fail due to CBT memory issue. It took vmware a week to acknowledge the bug does indeed exist in 6.0. They have provided no ETA on a hotfix or patch. As Bill mentioned, disabling cbt does resolve the issue. Vmware has yet to publish a Kb detailing the problem. If/when I see it, I'll gladly share here.

Hi. I have an engineer working on it and have given a ton of logs to them to the point that they can now replicate the issue at VMware.

If possible, can I get your VMware case number to give my engineer so he can look at your logs as well?

My temporary solution was to revert my ESXI hosts back to 5.5 and use the VCenter 6 appliance. Works the BEST it has ever worked!
I needed the CBT to function since 3-4 hour backups each night got old real quick :P

Any update on this from VMWARE i have the same problem

Do you have the ticket from VMWARE ?

Thanks !

They are working on a patch; but are unable to provide any ETA. They have confirmed and acknowledged the problem, however.

Josh

Josh can you give me your ticket at VMWARE so i can have updates on it

Thanks !

Do you have the tickets at VMWARE so i can relate to that ?

Ok ive spoke with VMWARE too for my case i had open and they found the main case of this issue wich is: 15632501403

Like you said they told me the same thing : they can't provide any ETA

Thanks at least we know it will be fix...soon i hope :)

Sorry Patrick, I was away from email. Glad you were able to find the main case #.

Josh

Patch is available: http://kb.vmware.com/kb/2116126

Thanks Bill!