Avamar: VMware Image Restore Runs for Hours, Showing Progress in GB or TB, but Fails with "Timeout on wait for spawned avtar process to complete"

VMware image restore runs for hours, shows GB or TB progress, but fails with:

avvcbimage Error <0000>: [IMG0011] Timeout on wait for spawned avtar process to complete

In the restore log, notice that the VMware plug-in has disconnected from the virtual machine after restoring one of the virtual disks:

 avvcbimage Info <9679>: Virtual disk connection to '[datastore] testvm-Restore_1714653538862/testvm-Restore_4.vmdk' has been closed
 avvcbimage Info <40654>: isExitOK()=0
 avvcbimage Info <40654>: isExitOK()=0
 avvcbimage Info <12060>: Getting next pax element in VMFile directory
 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Disconnect: Disconnect.

 avvcbimage Info <42222>: Using vSphere revertSnapshotTask snapshot moref (snapshot-414916)
 avvcbimage Info <14629>: Snapshot (snapshot-414916) removal for VM '[datastore] testvm-Restore1714653538862/Testvm-Restore.vmx' task queued, sleep for 1 sec

After 300 s, notice that the avtar process is still running and needs more time. By default, the subprocess timeout is 5 minutes or 300 s.

avvcbimage Error <0000>: [IMG0011] Timeout on wait for spawned avtar process to complete

For example, in the following log, the image plug-in has waited 5 minutes:

2024-05-03 12:53:04 avvcbimage Error <0000>: [IMG0011] Timeout on wait for spawned avtar process to complete

Later, in the log, notice that the avtar process successfully was completed (code 0), but it required 1 hour, 32 minutes, and 23 s:

2024-05-03 14:25:27 avvcbimage Info <6688>: Process 16763 (/usr/local/avamarclient/bin/avtar) finished (code 0: success)

In the avtar log, the status lines (printed every 15 minutes by default) show that during this time, avtar was still restoring a virtual disk. However, because the image plug-in is disconnected, this data is not being written to the virtual machine.

2024-05-03 13:00:20 avtar Info <8688>: Status 2024-05-03 13:00:20, 24 files, 6 directories, 2,404 GB (24 files, 4,807 GB, 100.00% new) 1250MB  82% CPU  VMFiles/5/virtdisk-flat.vmdk

The exact root cause is under investigation. However, the common trigger in each case is when the virtual disk size is not a multiple of 8192 KB or 1,048,576 KB.

Workarounds:

• Perform an instant access restore instead of an image restore. This type of restore is immune from this issue.

OR

• Download and install the latest version of the GoAV tool from Avamar. A validate-size feature was added in GoAV version 1.72.

For more information about validate-size feature, see the Additional Info section of this article or GoAV documentation. 

1. Using GoAV, run the command: 

./goav vm validate-size 

2. To resize the virtual machine:
   1. In the vSphere client, locate the virtual machine.
   2. Edit the virtual machine and select the identified disk using the tool.
   3. Change the units to MB, and from the GoAV tool set the size to RESIZE TO.
3. Start a new backup in Avamar. After the backup is complete, perform a new image restore on the latest backup to confirm the issue is resolved. 

More information about GoAV validate-size feature: 
This feature detects virtual machines with virtual disk sizes that are not multiples of 8192 KB or 1,048,576 KB (1 MB). If found, it recommends a newer, larger size to increase the virtual disk. 

./goav vm  validate-size --help
Validate Virtual Machine disk size by checking each disk for the VM on vcenter.
Verifies that disk sizes are properly divisible by 1MB and 8KB.

Usage:
  goav vm validate-size [flags]

Examples:
./goav vm validate-size --name testing8kb-invalidlength --vc myvcenter.fqdn.tld


DEVICE KEY |                                VMDK                                 | DISK SIZE |  8KB  |  1MB  | RESIZE TO
-------------+---------------------------------------------------------------------+-----------+-------+-------+------------
  2001       | [localDatastore] testing8kb-invalidlength/invalidSize.vmdk | 1536000   | false | false | 2 MB


Flags:
  -h, --help          help for validate-size
      --hide-valid    Set output to hide valid VMs
      --name string   VM Name
      --prompt        Prompts to select vCenters
      --vc string     Vcenter Name

Global Flags:
  -d, --debug      debug output
  -f, --force      Ignore Configuration
  -n, --noheader   Do not display header

Commands Explained:

goav vm validate-size 

• Retrieves a list of Virtual Machines (VMs) from Avamar
• Establishes a connection to each corresponding Virtual Machine's vCenter
• Gets the virtual disk size and checks if the size is a multiple of 8 KB or 1 MB
• If the disk size is not valid, it recommends a size to increase the disk in VMware.

 Optional flags:

--hide-valid  -  Does print the VM names that have valid disk sizes  
--name   The virtual machine name to check  
--vc   The virtual center server to checks
--prompts Prompts to select vCenters

Example output: 

admin@ave:~/>: ./goav vm  validate-size --name 1mb-clone 

========================= vc.example.com  =========================


1mb-clone                                                                INVALID

  DEVICE KEY |                   VMDK                    |   DISK SIZE   | 8KB  |  1MB  | RESIZE TO
-------------+-------------------------------------------+---------------+------+-------+------------
  2000       | [Datastore] 1mb-clone/1mb-clone.vmdk | 1572864 Bytes | true | false | 2 MB