Backup Failing Again!

#1

Seem to be running into multiple issues with VerticalBackup now. Over the weekend our Daily backup has been failing.

One of the virtual machines backs up fine, however, when it gets to the other virtual machine the backup fails.

2018-06-11 08:19:31.284898 INFO BACKUP_VM Backing up ts1, id: 2, vmx path: /vmfs/volumes/SSD/ts1/ts1.vmx, guest os: windows9_64Guest
2018-06-11 08:19:31.316623 INFO BACKUP_PREV Last backup at revision 25 found
2018-06-11 08:19:32.258776 INFO SNAPSHOT_POWER Virtual machine ts1 is powered on
2018-06-11 08:19:32.259048 INFO SNAPSHOT_REMOVE Removing all snapshots of ts1
2018-06-11 08:19:33.519521 INFO SNAPSHOT_CREATE Creating a new virtual machine snapshot for ts1
2018-06-11 08:19:50.077232 INFO COMMAND_OUTPUT Create Snapshot:
2018-06-11 08:19:50.077536 INFO COMMAND_OUTPUT Create snapshot failed
2018-06-11 08:19:50.077612 ERROR COMMAND_RUN Command '/bin/vim-cmd vmsvc/snapshot.create 2 2018-06-11-08-19-33 'Created by Vertical Backup 1.1.5' 0 1' returned 1
2018-06-11 08:19:50.077735 INFO SNAPSHOT_REMOVE Removing all snapshots of ts1
#2

A snapshot consolidation through the vSphere client should fix it, but do you see anything in the log file (like /vmfs/volumes/datastore/vm/vmware.log) that explains the failure?

#3

Sorry, I should have mentioned I’ve already tried to consolidate the snapshots in VmWare, this didn’t resolve the issues as I tried running the command manually from Putty after consolidating. Although, it appears the backup run fine last night by itself (cron).

Please see below log from the VM that was failing.

 
2018-06-11T08:40:41.199Z| svga| I125: MKSScreenShotMgr: Taking a screenshot
2018-06-11T08:40:58.334Z| vmx| I125: VigorTransportProcessClientPayload: opID=a365592b seq=174607: Receiving Snapshot.Consolidate request.
2018-06-11T08:40:58.339Z| vmx| I125: SnapshotVMX_Consolidate: Starting online snapshot consolidate operation.
2018-06-11T08:40:58.339Z| vmx| I125: Vix: [144254 mainDispatch.c:4234]: VMAutomation_ReportPowerOpFinished: statevar=3, newAppState=1880, success=1 additionalError=0
2018-06-11T08:40:58.339Z| vmx| I125: Turning on snapshot info cache. VM=ts1.vmx.
2018-06-11T08:40:58.340Z| vmx| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : open successful (1114133) size = 0, hd = 0. Type 3
2018-06-11T08:40:58.340Z| vmx| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : closed.
2018-06-11T08:40:58.340Z| vmx| I125: SNAPSHOT: Turning on snapshot disk cache.
2018-06-11T08:40:58.340Z| vmx| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : open successful (21) size = 64424509440, hd = 0. Type 3
2018-06-11T08:40:58.341Z| vmx| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : closed.
2018-06-11T08:40:58.341Z| vmx| I125: VigorTransport_ServerSendResponse opID=a365592b seq=174607: Completed Snapshot request.
2018-06-11T08:40:58.341Z| vmx| I125: Turning off snapshot info cache.
2018-06-11T08:40:58.341Z| vmx| I125: Turning off snapshot disk cache.
2018-06-11T08:40:58.341Z| vmx| I125: ConsolidateEnd: Snapshot consolidate complete: The operation completed successfully (0).
2018-06-11T08:40:58.341Z| vmx| I125: Vix: [144254 mainDispatch.c:4234]: VMAutomation_ReportPowerOpFinished: statevar=3, newAppState=1881, success=1 additionalError=0
2018-06-11T09:06:05.219Z| vmx| I125: VigorTransportProcessClientPayload: opID=vim-cmd-f1-5a7d seq=175210: Receiving Snapshot.Take request.
2018-06-11T09:06:05.220Z| vmx| I125: SnapshotVMX_TakeSnapshot start: '2018-06-11-09-06-04', deviceState=0, lazy=0, quiesced=1, forceNative=0, tryNative=1, saveAllocMaps=0 cb=D6346AA20, cbData=D64D45860
2018-06-11T09:06:05.222Z| vmx| I125: DISKLIB-LIB_CREATE   : DiskLibCreateCreateParam: vmfsSparse grain size is set to 1 for '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk'
2018-06-11T09:06:05.222Z| vmx| I125: SNAPSHOT: SnapshotPrepareTakeDoneCB: Prepare phase complete (The operation completed successfully).
2018-06-11T09:06:05.440Z| vcpu-0| I125: ToolsBackup: changing quiesce state: IDLE -> STARTED
2018-06-11T09:06:14.845Z| vmx| I125: GuestRpcSendTimedOut: message to toolbox-dnd timed out.
2018-06-11T09:06:17.604Z| vcpu-0| I125: ToolsBackup: changing quiesce state: STARTED -> COMMITTED
2018-06-11T09:06:17.604Z| vcpu-0| I125: Destroying virtual dev for scsi0:0 vscsi=8433
2018-06-11T09:06:17.604Z| vcpu-0| I125: VMMon_VSCSIStopVports: No such target on adapter
2018-06-11T09:06:17.606Z| vcpu-0| I125: SnapshotVMXTakeSnapshotWork: Transition to mode 0.
2018-06-11T09:06:17.606Z| vcpu-0| I125: Closing all the disks of the VM.
2018-06-11T09:06:17.606Z| vcpu-0| I125: Closing disk 'scsi0:0'
2018-06-11T09:06:17.606Z| vcpu-0| I125: SVMotion_DiskCloseCB: Closing disks in svmPhase 0. Not destroying mirror node.
2018-06-11T09:06:17.607Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : closed.
2018-06-11T09:06:17.608Z| vcpu-0| I125: SNAPSHOT: SnapshotConfigInfoReadEx: Creating new snapshot dictionary, '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmsd.usd'.
2018-06-11T09:06:17.614Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : open successful (1114133) size = 0, hd = 0. Type 3
2018-06-11T09:06:17.614Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : closed.
2018-06-11T09:06:17.635Z| vcpu-0| I125: SNAPSHOT: SnapshotDumperOpenFromInfo: Creating checkpoint file /vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-Snapshot227.vmsn
2018-06-11T09:06:17.645Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : open successful (29) size = 64424509440, hd = 0. Type 3
2018-06-11T09:06:17.647Z| vcpu-0| I125: DISKLIB-LIB_CREATE   : DiskLibCreateCreateParam: vmfsSparse grain size is set to 1 for '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk'
2018-06-11T09:06:17.647Z| vcpu-0| I125: DISKLIB-LIB_CREATE   : CREATE CHILD: "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk" -- vmfsSparse cowGran=1 allocType=0 policy=''
2018-06-11T09:06:17.647Z| vcpu-0| I125: DISKLIB-LIB_CREATE   : CREATE-CHILD: Creating disk backed by 'file'
2018-06-11T09:06:17.659Z| vcpu-0| I125: DISKLIB-VMFS_SPARSE : VmfsSparseExtentCreate: "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : success
2018-06-11T09:06:17.661Z| vcpu-0| I125: DISKLIB-DSCPTR: "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk" : creation successful.
2018-06-11T09:06:17.666Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : open successful (17) size = 126976, hd = 0. Type 9
2018-06-11T09:06:17.671Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : closed.
2018-06-11T09:06:17.671Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : closed.
2018-06-11T09:06:17.672Z| vcpu-0| A100: ConfigDB: Setting scsi0:0.fileName = "ts1-000001.vmdk"
2018-06-11T09:06:17.680Z| vcpu-0| I125: Checkpoint_Unstun: vm stopped for 75563 us
2018-06-11T09:06:17.680Z| vcpu-0| I125: SCSI: switching scsi0 to push completion mode
2018-06-11T09:06:17.680Z| vcpu-0| A100: ConfigDB: Setting scsi0:0.redo = ""
2018-06-11T09:06:17.680Z| vcpu-0| I125: DISK: OPEN scsi0:0 '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk' persistent R[]
2018-06-11T09:06:17.681Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : open successful (10) size = 126976, hd = 23594142. Type 9
2018-06-11T09:06:17.681Z| vcpu-0| I125: DISKLIB-DSCPTR: Opened [0]: "ts1-000001-delta.vmdk" (0xa)
2018-06-11T09:06:17.681Z| vcpu-0| I125: DISKLIB-LINK  : Opened '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk' (0xa): vmfsSparse, 125829120 sectors / 60 GB.
2018-06-11T09:06:17.682Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : open successful (14) size = 64424509440, hd = 30475543. Type 3
2018-06-11T09:06:17.682Z| vcpu-0| I125: DISKLIB-DSCPTR: Opened [0]: "ts1-flat.vmdk" (0xe)
2018-06-11T09:06:17.682Z| vcpu-0| I125: DISKLIB-LINK  : Opened '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk' (0xe): vmfs, 125829120 sectors / 60 GB.
2018-06-11T09:06:17.682Z| vcpu-0| I125: DISKLIB-CHAINESX : ChainESXOpenSubChain:(0) fid = 30475543, extentType = 2
2018-06-11T09:06:17.682Z| vcpu-0| I125: DISKLIB-CHAINESX : ChainESXOpenSubChain:(1) fid = 23594142, extentType = 0
2018-06-11T09:06:17.682Z| vcpu-0| I125: DISKLIB-LIB   : Opened "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk" (flags 0xa, type vmfs).
2018-06-11T09:06:17.682Z| vcpu-0| I125: DISK: Disk '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk' has UUID '60 00 c2 91 99 dd 2d 20-22 f2 6b 57 23 8a b3 21'
2018-06-11T09:06:17.682Z| vcpu-0| I125: DISK: OPEN '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk' Geo (7832/255/63) BIOS Geo (0/0/0)
2018-06-11T09:06:17.682Z| vcpu-0| I125: Creating virtual dev for 'scsi0:0'.
2018-06-11T09:06:17.682Z| vcpu-0| I125: DumpDiskInfo: scsi0:0 createType=11, capacity = 125829120, numLinks = 2, allocationType = 0
2018-06-11T09:06:17.682Z| vcpu-0| I125: SCSIDiskESXPopulateVDevDesc: Using FS backend
2018-06-11T09:06:17.682Z| vcpu-0| I125: DISKUTIL: scsi0:0 : geometry=7832/255/63
2018-06-11T09:06:17.682Z| vcpu-0| I125: SCSIFilterESXAttachCBRCInt: CBRC not enabled or opened without filters,skipping CBRC           filter attach.
2018-06-11T09:06:17.682Z| vcpu-0| I125: SCSIFilterSBDAttachCBRC: device scsi0:0 is not SBD. Skipping CBRC attach SBD way.
2018-06-11T09:06:17.682Z| vcpu-0| I125: VMXNET3 user: Ethernet0 Driver Info: version = 5414838 gosBits = 2 gosType = 2, gosVer = 40960, gosMisc = 212
2018-06-11T09:06:17.682Z| vcpu-0| I125: SnapshotVMXTakeSnapshotWork: Transition to mode 1.
2018-06-11T09:06:17.704Z| vcpu-0| I125: ToolsBackup: changing quiesce state: COMMITTED -> FINISHING
2018-06-11T09:06:17.765Z| vcpu-1| I125: HBACommon: First write on scsi0:0.fileName='/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk'
2018-06-11T09:06:17.765Z| vcpu-1| I125: DDB: "longContentID" = "6d84565477d9d082b91b2fcfe7f6847e" (was "abf00422c03cdb37955b2406825d6d34")
2018-06-11T09:06:17.769Z| vcpu-1| I125: DISKLIB-CHAIN : DiskChainUpdateContentID: old=0x825d6d34, new=0xe7f6847e (6d84565477d9d082b91b2fcfe7f6847e)
2018-06-11T09:06:18.713Z| vcpu-1| I125: Msg_Post: Warning
2018-06-11T09:06:18.713Z| vcpu-1| I125: [msg.snapshot.quiesce.vmerr] The guest OS has reported an error during quiescing.
2018-06-11T09:06:18.713Z| vcpu-1| I125+ The error code was: 3
2018-06-11T09:06:18.713Z| vcpu-1| I125+ The error message was: Quiesce operation aborted
2018-06-11T09:06:18.713Z| vcpu-1| I125: ----------------------------------------
2018-06-11T09:06:18.714Z| vcpu-1| I125: ToolsBackup: changing quiesce state: FINISHING -> ERROR_WAIT
2018-06-11T09:06:20.729Z| vcpu-1| I125: ToolsBackup: changing quiesce state: ERROR_WAIT -> IDLE
2018-06-11T09:06:20.729Z| vcpu-1| I125: ToolsBackup: changing quiesce state: IDLE -> DONE
2018-06-11T09:06:20.733Z| vcpu-1| I125: SNAPSHOT: SnapshotDeleteWork '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmx' : 227
2018-06-11T09:06:20.733Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : open successful (21) size = 16904192, hd = 0. Type 9
2018-06-11T09:06:20.733Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : closed.
2018-06-11T09:06:20.734Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : open successful (21) size = 64424509440, hd = 0. Type 3
2018-06-11T09:06:20.734Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : closed.
2018-06-11T09:06:20.743Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : open successful (1114133) size = 0, hd = 0. Type 9
2018-06-11T09:06:20.743Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : closed.
2018-06-11T09:06:20.748Z| vcpu-1| I125: SnapshotVMXTakeSnapshotComplete: Done with snapshot '2018-06-11-09-06-04': 227
2018-06-11T09:06:20.748Z| vcpu-1| I125: SnapshotVMXTakeSnapshotComplete: Snapshot 227 failed: Failed to quiesce the virtual machine (29).
2018-06-11T09:06:20.748Z| vcpu-1| I125: SnapshotVMXTakeSnapshotComplete: Cleaning up incomplete snapshot 227.
2018-06-11T09:06:20.748Z| vcpu-1| I125: SnapshotVMXTakeSnapshotComplete: Starting snapshot consolidation for cleaning up incomplete snapshots.
2018-06-11T09:06:20.749Z| vcpu-1| I125: SnapshotVMX_Consolidate: Starting online snapshot consolidate operation.
2018-06-11T09:06:20.749Z| vcpu-1| I125: Vix: [144264 mainDispatch.c:4234]: VMAutomation_ReportPowerOpFinished: statevar=3, newAppState=1880, success=1 additionalError=0
2018-06-11T09:06:20.749Z| vcpu-1| I125: Turning on snapshot info cache. VM=ts1.vmx.
2018-06-11T09:06:20.751Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : open successful (1114133) size = 0, hd = 0. Type 9
2018-06-11T09:06:20.751Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : closed.
2018-06-11T09:06:20.751Z| vcpu-1| I125: SNAPSHOT: Turning on snapshot disk cache.
2018-06-11T09:06:20.751Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : open successful (21) size = 16904192, hd = 0. Type 9
2018-06-11T09:06:20.751Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : closed.
2018-06-11T09:06:20.751Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : open successful (21) size = 64424509440, hd = 0. Type 3
2018-06-11T09:06:20.751Z| vcpu-1| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : closed.
2018-06-11T09:06:20.751Z| vcpu-1| I125: WORKER: Creating new group with numThreads=1 (16)
2018-06-11T09:06:20.751Z| vcpu-1| I125: WORKER: Creating new group with numThreads=1 (16)
2018-06-11T09:06:20.752Z| vcpu-0| I125: Destroying virtual dev for scsi0:0 vscsi=8442
2018-06-11T09:06:20.752Z| vcpu-0| I125: VMMon_VSCSIStopVports: No such target on adapter
2018-06-11T09:06:20.753Z| vcpu-0| I125: Closing disk 'scsi0:0'
2018-06-11T09:06:20.753Z| vcpu-0| I125: SVMotion_DiskCloseCB: Closing disks in svmPhase 0. Not destroying mirror node.
2018-06-11T09:06:20.754Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : closed.
2018-06-11T09:06:20.754Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : closed.
2018-06-11T09:06:20.754Z| vcpu-0| I125: Checkpoint_Unstun: vm stopped for 2464 us
2018-06-11T09:06:20.754Z| vcpu-0| I125: SCSI: switching scsi0 to push completion mode
2018-06-11T09:06:20.754Z| vcpu-0| A100: ConfigDB: Setting scsi0:0.redo = ""
2018-06-11T09:06:20.754Z| vcpu-0| I125: DISK: OPEN scsi0:0 '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk' persistent R[]
2018-06-11T09:06:20.755Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : open successful (8) size = 16904192, hd = 30803223. Type 9
2018-06-11T09:06:20.755Z| vcpu-0| I125: DISKLIB-DSCPTR: Opened [0]: "ts1-000001-delta.vmdk" (0x8)
2018-06-11T09:06:20.755Z| vcpu-0| I125: DISKLIB-LINK  : Opened '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk' (0x8): vmfsSparse, 125829120 sectors / 60 GB.
2018-06-11T09:06:20.755Z| vcpu-0| I125: DISKLIB-CHAINESX : ChainESXOpenSubChain:(0) fid = 30803223, extentType = 0
2018-06-11T09:06:20.755Z| vcpu-0| I125: DISKLIB-LIB   : Opened "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk" (flags 0x8, type vmfsSparse).
2018-06-11T09:06:20.756Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : open successful (522) size = 64424509440, hd = 33555799. Type 3
2018-06-11T09:06:20.756Z| vcpu-0| I125: DISKLIB-DSCPTR: Opened [0]: "ts1-flat.vmdk" (0x20a)
2018-06-11T09:06:20.756Z| vcpu-0| I125: DISKLIB-LINK  : Opened '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk' (0x20a): vmfs, 125829120 sectors / 60 GB.
2018-06-11T09:06:20.756Z| vcpu-0| I125: DISKLIB-LIB   : Opened "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk" (flags 0x20a, type vmfs).
2018-06-11T09:06:20.756Z| vcpu-0| I125: DISKLIB-CHAINESX : ChainESXOpenSubChain:(0) fid = 33555799, extentType = 2
2018-06-11T09:06:20.756Z| vcpu-0| I125: DISKLIB-CHAINESX : ChainESXOpenSubChain:(1) fid = 30803223, extentType = 0
2018-06-11T09:06:20.756Z| vcpu-0| I125: DISK: Disk '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk' has UUID '60 00 c2 91 99 dd 2d 20-22 f2 6b 57 23 8a b3 21'
2018-06-11T09:06:20.756Z| vcpu-0| I125: DISK: OPEN '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk' Geo (7832/255/63) BIOS Geo (0/0/0)
2018-06-11T09:06:20.756Z| vcpu-0| I125: ConsolidateDiskOpenCB: Opening disk node 'scsi0:0' for combining '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk' -> '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk'.
2018-06-11T09:06:20.757Z| vcpu-0| I125: DISKLIB-LIB_MISC   : Opening mirror node /vmfs/devices/svm/1a50518-2000557-svmmirror
2018-06-11T09:06:20.757Z| vcpu-0| I125: Creating virtual dev for 'scsi0:0'.
2018-06-11T09:06:20.757Z| vcpu-0| I125: DumpDiskInfo: scsi0:0 createType=11, capacity = 125829120, numLinks = 2, allocationType = 0
2018-06-11T09:06:20.757Z| vcpu-0| I125: SCSIDiskESXPopulateVDevDesc: Using FS backend
2018-06-11T09:06:20.757Z| vcpu-0| I125: DISKUTIL: scsi0:0 : geometry=7832/255/63
2018-06-11T09:06:20.757Z| vcpu-0| I125: SCSIFilterESXAttachCBRCInt: CBRC not enabled or opened without filters,skipping CBRC           filter attach.
2018-06-11T09:06:20.757Z| vcpu-0| I125: SCSIFilterSBDAttachCBRC: device scsi0:0 is not SBD. Skipping CBRC attach SBD way.
2018-06-11T09:06:20.757Z| vcpu-0| I125: VMXNET3 user: Ethernet0 Driver Info: version = 5414838 gosBits = 2 gosType = 2, gosVer = 40960, gosMisc = 212
2018-06-11T09:06:20.770Z| Worker#0| I125: DISKLIB-LIB   : DiskLib_IsCombinePossible: Upward Combine 2 links at 0. Need 0 MB of free space (67595 MB available)
2018-06-11T09:06:20.770Z| vmx| I125: ConsolidateMirrorCombineStart: Combine '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk' -> '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk' (node = scsi0:0): 2 links starting from 0. usesCurrent = 1, isNative = 0 
2018-06-11T09:06:20.770Z| vmx| I125: Mirror_DiskCopy: Starting disk copy.
2018-06-11T09:06:20.972Z| vcpu-0| I125: Destroying virtual dev for scsi0:0 vscsi=8443
2018-06-11T09:06:20.972Z| vcpu-0| I125: VMMon_VSCSIStopVports: No such target on adapter
2018-06-11T09:06:20.977Z| vcpu-0| I125: Closing disk 'scsi0:0'
2018-06-11T09:06:20.977Z| vcpu-0| I125: SVMotion_DiskCloseCB: Closing disks in svmPhase 0. Not destroying mirror node.
2018-06-11T09:06:20.977Z| vcpu-0| I125: ConsolidateDiskCloseCB: Closing disk node 'scsi0:0' after combining '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001.vmdk' -> '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk'.
2018-06-11T09:06:20.977Z| vcpu-0| I125: DDB: "longContentID" = "6d84565477d9d082b91b2fcfe7f6847e" (was "abf00422c03cdb37955b2406825d6d34")
2018-06-11T09:06:20.998Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : closed.
2018-06-11T09:06:20.998Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : closed.
2018-06-11T09:06:20.998Z| vcpu-0| A100: ConfigDB: Setting scsi0:0.fileName = "ts1.vmdk"
2018-06-11T09:06:20.999Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : open successful (1115153) size = 0, hd = 0. Type 9
2018-06-11T09:06:20.999Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-000001-delta.vmdk" : closed.
2018-06-11T09:06:21.003Z| vcpu-0| I125: Checkpoint_Unstun: vm stopped for 30834 us
2018-06-11T09:06:21.003Z| vcpu-0| I125: SCSI: switching scsi0 to push completion mode
2018-06-11T09:06:21.004Z| vcpu-0| A100: ConfigDB: Setting scsi0:0.redo = ""
2018-06-11T09:06:21.004Z| vcpu-0| I125: DISK: OPEN scsi0:0 '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk' persistent R[]
2018-06-11T09:06:21.004Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1-flat.vmdk" : open successful (10) size = 64424509440, hd = 34080087. Type 3
2018-06-11T09:06:21.004Z| vcpu-0| I125: DISKLIB-DSCPTR: Opened [0]: "ts1-flat.vmdk" (0xa)
2018-06-11T09:06:21.004Z| vcpu-0| I125: DISKLIB-LINK  : Opened '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk' (0xa): vmfs, 125829120 sectors / 60 GB.
2018-06-11T09:06:21.004Z| vcpu-0| I125: DISKLIB-LIB   : Opened "/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk" (flags 0xa, type vmfs).
2018-06-11T09:06:21.004Z| vcpu-0| I125: DISK: Disk '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk' has UUID '60 00 c2 91 99 dd 2d 20-22 f2 6b 57 23 8a b3 21'
2018-06-11T09:06:21.004Z| vcpu-0| I125: DISK: OPEN '/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk' Geo (7832/255/63) BIOS Geo (0/0/0)
2018-06-11T09:06:21.004Z| vcpu-0| I125: Creating virtual dev for 'scsi0:0'.
2018-06-11T09:06:21.004Z| vcpu-0| I125: DumpDiskInfo: scsi0:0 createType=11, capacity = 125829120, numLinks = 1, allocationType = 1
2018-06-11T09:06:21.004Z| vcpu-0| I125: SCSIDiskESXPopulateVDevDesc: Using FS backend
2018-06-11T09:06:21.004Z| vcpu-0| I125: DISKUTIL: scsi0:0 : geometry=7832/255/63
2018-06-11T09:06:21.004Z| vcpu-0| I125: SCSIFilterESXAttachCBRCInt: CBRC not enabled or opened without filters,skipping CBRC           filter attach.
2018-06-11T09:06:21.005Z| vcpu-0| I125: SCSIFilterSBDAttachCBRC: device scsi0:0 is not SBD. Skipping CBRC attach SBD way.
2018-06-11T09:06:21.005Z| vcpu-0| I125: VMXNET3 user: Ethernet0 Driver Info: version = 5414838 gosBits = 2 gosType = 2, gosVer = 40960, gosMisc = 212
2018-06-11T09:06:21.005Z| vcpu-0| I125: VigorTransport_ServerSendResponse opID=vim-cmd-f1-5a7d seq=175210: Completed Snapshot request.
2018-06-11T09:06:21.005Z| vcpu-0| I125: Turning off snapshot info cache.
2018-06-11T09:06:21.005Z| vcpu-0| I125: Turning off snapshot disk cache.
2018-06-11T09:06:21.005Z| vcpu-0| I125: ConsolidateEnd: Snapshot consolidate complete: The operation completed successfully (0).
2018-06-11T09:06:21.005Z| vcpu-0| I125: Vix: [144262 mainDispatch.c:4234]: VMAutomation_ReportPowerOpFinished: statevar=3, newAppState=1881, success=1 additionalError=0
2018-06-11T09:06:21.963Z| vcpu-0| I125: HBACommon: First write on scsi0:0.fileName='/vmfs/volumes/4c2e0db0-c42d9b1e-ed3c-0025903c61d8/ts1/ts1.vmdk'
2018-06-11T09:06:21.964Z| vcpu-0| I125: DDB: "longContentID" = "df30b924d63f37711e3a509cc61ada15" (was "6d84565477d9d082b91b2fcfe7f6847e")
2018-06-11T09:06:21.972Z| vcpu-0| I125: DISKLIB-CHAIN : DiskChainUpdateContentID: old=0xe7f6847e, new=0xc61ada15 (df30b924d63f37711e3a509cc61ada15)
2018-06-11T09:06:48.713Z| vcpu-0| I125: Guest: *** WARNING: GuestInfo collection interval longer than expected; actual=60 sec, expected=30 sec. ***
2018-06-11T09:06:48.713Z| vcpu-0| I125:
#4

I think this is the issue:

2018-06-11T09:06:18.713Z| vcpu-1| I125: [msg.snapshot.quiesce.vmerr] The guest OS has reported an error during quiescing.
2018-06-11T09:06:18.713Z| vcpu-1| I125+ The error code was: 3
2018-06-11T09:06:18.713Z| vcpu-1| I125+ The error message was: Quiesce operation aborted

You can try running the backup command with the --no-quiesce option.