Crash Consistent and application consistent backup for the same job

[ricky73]

I'm using VDP 6.1 in ESXi 6 environment cluster to backup virtual machines and I noted the same Windows guest OS has different kind of backup:

Crash Consistent or application consistent backup

E.g. the same job for Windows 2008 sometimes gets Crash Consistent backup and it sometimes get application consistent backup?

So logs show for some day "application consistent backup and for other days "Crash Consistent backup"

What is the reason to get different types of backup for the same job? In this server there is no database.

thanks

[SavkoorSuhas]

Usually if there is a quiesce failure the restore point would be crash consistent. Else they appear as app consistent.

Should not be an issue if this is a non DB hosted VM.

# Suhas

[ricky73]

I'd like to set the kind of backup (quiescence or not quiescence) for my vm  backup.

For default behaviour, VDP makes application consistent backup and if It fails, it can fall back to non quiescence backup.

How can I understand because quiescence fails?!

[SavkoorSuhas]

That would be in the logs.

The logs are at:

/usr/local/avamarclient/var

The log we need is >backup-job-name>-*EPOCH*-vmimagew.log

You can search by keyword "VDP-" and it will take you to the part where the snapshot task is initiated.

# Suhas

[ricky73]

I can set backup only as crash consistent task?

[SavkoorSuhas]

This will be on VM level. You will have to disable quiescing for the VM.

Enabling and disabling Windows 2008 and later application-consistent quiescing on ESXi/ESX (1028881)...

# Suhas

[ricky73]

2017-07-02T23:59:41.576-02:00 avvcbimage Info <0000>: Snapshot 'VDP-14990327540ec0a30c3060e65dc2461f028d5226071386dfcc' creation for VM '[DS-27] NDCN01/NDCN01.vmx' task still in progress, sleep for 3 sec

2017-07-02T23:59:44.605-02:00 avvcbimage Warning <19733>: vSphere Task failed (quiesce, snapshot error=45): 'An error occurred while saving the snapshot: Failed to quiesce the virtual machine.'.

2017-07-02T23:59:44.605-02:00 avvcbimage Error <17775>: Snapshot 'VDP-14990327540ec0a30c3060e65dc2461f028d5226071386dfcc' creation for VM '[DS-27] NDCN01/NDCN01.vmx' task creation encountered a quiesce problem

2017-07-02T23:59:44.605-02:00 avvcbimage Warning <0000>: The VM could not be quiesced prior to snapshot creation and this backup will not be used as a base for subsequent CBT backups if successful.

2017-07-02T23:59:44.605-02:00 avvcbimage Warning <40711>:     Consider using the pre-freeze and post-thaw scripts to facilitate VM quiescing

2017-07-02T23:59:44.605-02:00 avvcbimage Warning <41146>:     This error might caused by the pre-freeze script returning a non-zero error code.

2017-07-02T23:59:44.605-02:00 avvcbimage Info <40731>: Trying to consolidate disks for moref 'vm-390'.

2017-07-02T23:59:44.605-02:00 avvcbimage Info <0000>: SnapshotManager - consolidateVM, vm-390

2017-07-02T23:59:44.605-02:00 avvcbimage Info <0000>: SnapshotManager: POST to /snapshotmanager/vm/vm-390/action/consolidate, payload()

2017-07-02T23:59:44.861-02:00 avvcbimage Info <0000>: AvSnapMgr::postData Succeeded

2017-07-02T23:59:44.861-02:00 avvcbimage Info <0000>: POST: curl_easy_getinfo - passed. HTTPCode: 202

2017-07-02T23:59:44.861-02:00 avvcbimage Info <0000>: AvSnapMgr::postData Succeeded

2017-07-02T23:59:44.861-02:00 avvcbimage Info <0000>: SnapshotManagmer: consolidateVM successful, task moref:task-19835 for vm vm-390

2017-07-02T23:59:44.869-02:00 avvcbimage Info <0000>: VM Disk Consolidation for '[DS-27] NDCN01/NDCN01.vmx' task still in progress, sleep for 3 sec

2017-07-02T23:59:47.895-02:00 avvcbimage Info <14632>: VM Disk Consolidation for '[DS-27] NDCN01/NDCN01.vmx' task completed, moref=

2017-07-02T23:59:47.896-02:00 avvcbimage Info <14627>: Creating snapshot 'VDP-14990327540ec0a30c3060e65dc2461f028d5226071386dfcc', quieceFS=0

2017-07-02T23:59:47.896-02:00 avvcbimage Info <0000>: SnapshotManager: createSnapshot for vmMoref = vm-390

2017-07-02T23:59:47.896-02:00 avvcbimage Info <0000>: SnapshotManager: POST to /snapshotmanager/vm/vm-390/action/createSnapshot, payload({

  "snapshotName": "VDP-14990327540ec0a30c3060e65dc2461f028d5226071386dfcc",

  "snapshotDesc": "Created by VDP workorder MBS - NDCN - WebPres-MBS - NDCN - WebPres-1499032740024 on GMT-Sun Jul 02 21:59:14 2017",

  "quiesceFileSystem": "false"

})

2017-07-02T23:59:48.130-02:00 avvcbimage Info <0000>: AvSnapMgr::postData Succeeded

...

...

...

What means?

I noted "task creation encountered a quiesce problem"

[SavkoorSuhas]

VDP would not tell much about quiesce failure.

The generic message you will see for quiesce failure is this:

2017-07-02T23:59:44.605-02:00 avvcbimage Error <17775>: Snapshot 'VDP-14990327540ec0a30c3060e65dc2461f028d5226071386dfcc' creation for VM '[DS-27] NDCN01/NDCN01.vmx' task creation encountered a quiesce problem

To understand why this failed, we will then need to see vmware.log

The easiest way is , open vmware.log for the NDCN01 VM and search by the VDP snapshot ID, VDP-14990327540ec0a30c3060e65dc2461f028d5226071386dfcc, it will take you right to the part where the snapshot task begins.

# Suhas

[ricky73]

here is hostd.log on server:

017-07-02T21:59:14.373Z [35E80B70 verbose 'Default' opID=7ffc7a30-b5 user=vpxuser:AUSL6\Administrator] AdapterServer: target='vim.VirtualMachine:694', method='createSnapshot'

017-07-02T21:59:14.373Z [35E80B70 info 'Vimsvc.TaskManager' opID=7ffc7a30-b5 user=vpxuser:AUSL6\Administrator] Task Created : haTask-694-vim.VirtualMachine.createSnapshot-226565444

017-07-02T21:59:14.374Z [34BE1B70 verbose 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx' opID=7ffc7a30-b5 user=vpxuser:AUSL6\Administrator] Create Snapshot: V

017-07-02T21:59:14.374Z [34BE1B70 info 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx' opID=7ffc7a30-b5 user=vpxuser:AUSL6\Administrator] State Transition (VM_

017-07-02T21:59:18.594Z [32E8CB70 verbose 'SoapAdapter'] Responded to service state request

017-07-02T21:59:21.222Z [35E80B70 verbose 'SoapAdapter'] Responded to service state request

017-07-02T21:59:24.678Z [34E42B70 verbose 'Default' opID=4f234e3a-eb user=vpxuser:AUSL6\Administrator] AdapterServer: target='vim.VirtualMachine:550', method='createSnapshot'

017-07-02T21:59:24.678Z [34E42B70 info 'Vimsvc.TaskManager' opID=4f234e3a-eb user=vpxuser:AUSL6\Administrator] Task Created : haTask-550-vim.VirtualMachine.createSnapshot-226565465

017-07-02T21:59:24.678Z [34BE1B70 verbose 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN02_1/NDCN02.vmx' opID=4f234e3a-eb user=vpxuser:AUSL6\Administrator] Create Snapshot:

017-07-02T21:59:24.679Z [34BE1B70 info 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN02_1/NDCN02.vmx' opID=4f234e3a-eb user=vpxuser:AUSL6\Administrator] State Transition (V

017-07-02T21:59:41.104Z [34E42B70 verbose 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx'] Updating current heartbeatStatus: yellow

017-07-02T21:59:44.384Z [34E42B70 verbose 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx'] Handling message _vmx1: A timeout occurred while communicating with

->

017-07-02T21:59:44.385Z [34E42B70 info 'Vimsvc.ha-eventmgr'] Event 4721 : Warning message on NDCN01 on vmw15.ausl6.it in ha-datacenter: A timeout occurred while communicating with VMware Too

017-07-02T21:59:44.386Z [34E42B70 info 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx'] Answered question _vmx1

017-07-02T21:59:44.386Z [33B91B70 verbose 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx'] Create Snapshot translated error to vim.fault.GenericVmConfigFault

017-07-02T21:59:44.386Z [33B91B70 info 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx'] Create Snapshot failed: vim.fault.GenericVmConfigFault

017-07-02T21:59:44.386Z [33B91B70 verbose 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx'] Create Snapshot message: An error occurred while saving the snapshot

-> An error occurred while taking a snapshot: Failed to quiesce the virtual machine.

->

017-07-02T21:59:44.393Z [FF9C0B70 verbose 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx'] Time to gather Snapshot information ( read from disk,  build tree):

017-07-02T21:59:44.406Z [FF9C0B70 verbose 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx'] Time to gather config: 12 (msecs)

017-07-02T21:59:44.407Z [34E42B70 verbose 'Hbrsvc'] Replicator: ReconfigListener triggered for config VM 694

017-07-02T21:59:44.408Z [FF9C0B70 verbose 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx'] Time to gather snapshot file layout: 0 (msecs)

017-07-02T21:59:44.417Z [FF9C0B70 warning 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx'] Failed operation

017-07-02T21:59:44.418Z [FF9C0B70 info 'Vmsvc.vm:/vmfs/volumes/588b3953-46a33661-3ae1-e0071bcdb500/NDCN01/NDCN01.vmx'] State Transition (VM_STATE_CREATE_SNAPSHOT -> VM_STATE_ON)

017-07-02T21:59:44.418Z [32E8CB70 verbose 'Hostsvc'] Received state change for VM '694'

017-07-02T21:59:44.418Z [FF9C0B70 info 'Vimsvc.TaskManager'] Task Completed : haTask-694-vim.VirtualMachine.createSnapshot-226565444 Status error

017-07-02T21:59:44.418Z [32E8CB70 info 'Guestsvc.GuestFileTransferImpl'] Entered VmPowerStateListener

017-07-02T21:59:44.418Z [32E8CB70 info 'Guestsvc.GuestFileTransferImpl'] VmPowerStateListener succeeded

017-07-02T21:59:44.418Z [34E42B70 verbose 'Hbrsvc'] Replicator: VmReconfig ignoring VM 694 not configured for replication

017-07-02T21:59:44.418Z [32E8CB70 info 'Hbrsvc'] Replicator: powerstate change VM: 694 Old: 1 New: 1

017-07-02T21:59:44.419Z [32E8CB70 verbose 'Hbrsvc'] Replicator: Remove group no matching entry for VM (id=694)

[SavkoorSuhas]

Sounds like some tools timeout. Need the VMware.log for this VM, it will be more helpful than hostd.

# Suhas

[ricky73]

on client? I didn't see no similar file.

[SavkoorSuhas]

In the VM working directory.

/vmfs/volumes/<datastore>/<vm-name>

Zip the Vmware.log and attach it to this thread.

# Suhas

[ricky73]

here is file.

[SavkoorSuhas · Accepted solution]

There we go. Tools timeout:

2017-07-02T21:59:36.436Z| vmx| I120: Tools: Tools heartbeat timeout.

2017-07-02T21:59:44.383Z| vmx| I120: GuestRpcSendTimedOut: message to toolbox timed out.

2017-07-02T21:59:44.383Z| vmx| I120: Msg_Post: Warning

2017-07-02T21:59:44.383Z| vmx| I120: [msg.snapshot.quiesce.rpc_timeout] A timeout occurred while communicating with VMware Tools in the virtual machine.

2017-07-02T21:59:44.383Z| vmx| I120: ----------------------------------------

2017-07-02T21:59:44.386Z| vmx| I120: ToolsBackup: changing quiesce state: IDLE -> DONE

2017-07-02T21:59:44.386Z| vmx| I120: SnapshotVMXTakeSnapshotComplete: Done with snapshot 'VDP-14990327540ec0a30c3060e65dc2461f028d5226071386dfcc': 0

The tools version is 10240 which is 10.0.0

2017-07-02T00:01:51.765Z| vmx| I120: TOOLS installed legacy version 10240, available legacy version 9360

Use tools 10.0.9 which has this fix:

VMware Tools 10.0.9 Release Notes

Attempts to take a quiesced snapshot in a Windows Guest OS fails

# Suhas

[ricky73]

Thank you very much for precious information.

Can I update vmware tools to 10.0.9 on single vm without no upgrade for all my ESXi 5.5 (update3) hosts?

If I decided to make available vmware tools version, which you suggested, as default installation package to all ESXi hosts, what’s the build of 5.5 ESXi to    get?

thanks again

[SavkoorSuhas]

VMware tools should be backward compatible to host version.

You can manually download 10.0.9 and install it on your VM.

# Suhas

[ricky73]

It's possible to install update for ESXi 5.5 which include these vmware tools version?

I have vcenter 6 with ESXi 5.5 U3