Hey All,
Experiencing an issue where my jobs for VMs running on local disk are failing due to what appears to be a timeout on the take snapshot action. So at first I thought it was a timing issue, so I looked at that. It takes about 1 minute for quiesed snapshots to actually happen.
I found the other articles that mention you should change the --subprocesstimeout=600 parameter to the /usr/local/avamarclient/var/avvcbimageAll.cmd file, so I did that with no luck. I also tried increasing the snapshot removal time, with no luck.
Still, after applying this and rebooting the appliance no dice, even though the snapshot is completing before the VDP task, it's still failing.
VMware KB: vSphere Data Protection backup jobs fail intermittently
I had another VM work just fine that was on a local SSD, but any disks that are otherwise located on slow local magnetic disk fail.
Looking at the logs, it would appear the most interesting entry is bolded and underlined below, which leads me to the following article, which says, your storage sucks, figure out why your snapshots are taking so long. Anyone have an idea how to increase the timeout when snapshots are being "TAKEN" as opposed to being removed? Next up will try removing queising from the config.
2015-01-23T11:42:45.635+04:00 avvcbimage Info <19704>: DataStore Storage Info:ESX4_Local_ESXi_Installable capacity=1995012308992 free=1682109890560
2015-01-23T11:42:45.635+04:00 avvcbimage Info <19716>: DS Capacity=1995012308992 FreeSpace=1682109890560 / HD committed=57196542066 unCommitted=29917971642 unShared=57196542066
2015-01-23T11:42:46.584+04:00 avvcbimage Info <16001>: Found 2 disk(s), 0 snapshots, and 0 snapshot files, on the VMs datastore.
2015-01-23T11:42:46.584+04:00 avvcbimage Info <0000>: isExitOK()=0
2015-01-23T11:42:46.599+04:00 avvcbimage Info <19680>: vmAction runBackupScript: ()
2015-01-23T11:42:46.599+04:00 avvcbimage Info <19681>: vmAction runBackupScript: script is skipped because it is null
2015-01-23T11:42:46.600+04:00 avvcbimage Info <0000>: [IMG0009] Pre-snapshot script: completed successfully
2015-01-23T11:42:46.600+04:00 avvcbimage Info <9692>: a VM snapshot has been requested
2015-01-23T11:42:46.600+04:00 avvcbimage Info <14627>: Creating snapshot 'VDP-1422031366f2a36877d42af6c1a25a994c67b393fa02286299', quieceFS=1
2015-01-23T11:42:46.635+04:00 avvcbimage Info <14631>: Snapshot 'VDP-1422031366f2a36877d42af6c1a25a994c67b393fa02286299' creation for VM '[ESX4_Local_ESXi_Installable] <VMNAME>/<VMNAME>.vmx' task still in progress, sleep for 2 sec
2015-01-23T11:42:48.662+04:00 avvcbimage Info <14631>: Snapshot 'VDP-1422031366f2a36877d42af6c1a25a994c67b393fa02286299' creation for VM '[ESX4_Local_ESXi_Installable] <VMNAME>/<VMNAME>.vmx' task still in progress, sleep for 2 sec
2015-01-23T11:42:50.689+04:00 avvcbimage Info <14631>: Snapshot 'VDP-1422031366f2a36877d42af6c1a25a994c67b393fa02286299' creation for VM '[ESX4_Local_ESXi_Installable] <VMNAME>/<VMNAME>.vmx' task still in progress, sleep for 2 sec
2015-01-23T11:43:12.796+04:00 avvcbimage Warning <16004>: Soap fault detected, Query problem, Msg:'SOAP 1.1 fault: SOAP-ENV:Client [no subcode]
"Name or service not known"
Detail: getaddrinfo failed in tcp_connect()
'
2015-01-23T11:43:12.796+04:00 avvcbimage Error <17773>: Snapshot 'VDP-1422031366f2a36877d42af6c1a25a994c67b393fa02286299' creation for VM '[ESX4_Local_ESXi_Installable] <VMNAME>/<VMNAME>.vmx' task failed to start
2015-01-23T11:43:12.796+04:00 avvcbimage Info <19680>: vmAction runBackupScript: ()
2015-01-23T11:43:12.796+04:00 avvcbimage Info <19681>: vmAction runBackupScript: script is skipped because it is null
2015-01-23T11:43:12.796+04:00 avvcbimage Info <0000>: [IMG0009] Post-snapshot script: completed successfully
2015-01-23T11:43:12.796+04:00 avvcbimage FATAL <0000>: [IMG0003] The VMX '[ESX4_Local_ESXi_Installable] <VMNAME>/<VMNAME>.vmx' could not be snapshot.
2015-01-23T11:43:12.796+04:00 avvcbimage Info <9772>: Starting graceful (staged) termination, Create Snapshot failure. (wrap-up stage)
2015-01-23T11:43:12.796+04:00 avvcbimage Error <0000>: [IMG0009] createSnapshot: snapshot creation or pre/post snapshot script failed
2015-01-23T11:43:12.796+04:00 avvcbimage Error <0000>: [IMG0009] createSnapshot: snapshot creation/pre-script/post-script failed
2015-01-23T11:43:12.796+04:00 avvcbimage Info <0000>: isExitOK()=202
2015-01-23T11:43:12.796+04:00 avvcbimage Info <40370>: snapshot created:false NOMC:false ChangeBlTrackingAvail:true UsingChBl:true, ExitOK:false, cancelled:false, fatal: true
2015-01-23T11:43:12.796+04:00 avvcbimage Info <0000>: vcbimage_progress::terminate
2015-01-23T11:43:12.796+04:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_EndAccess: Disk access completed.
Basically the article says, your storage sucks, deal with it and get better storage.
2015-01-23T11:43:12.796+04:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Connect: Establish connection.
2015-01-23T11:43:12.796+04:00 avvcbimage Info <16041>: VDDK:VixDiskLibVim: VixDiskLibVim_AllowVMotion: Enable VMotion.
2015-01-23T11:43:12.798+04:00 avvcbimage Info <16038>: Final summary, cancelled/aborted 0, snapview 0, exitcode 202: plugin error 02
2015-01-23T11:43:14.907+04:00 avvcbimage Info <17819>: VixDiskLib vMotion reservation successfully released
--------------------------------------------------------------------------------------------------------
----- END avvcbimage log 2015-01-23 11:43:17 EST (1 warning, 4 errors, 1 fatal error)
--------------------------------------------------------------------------------------------------------
