Hi every one,
Actually I am using vSphere Data Protection 6.1.2 to back up our virtual machines and I am experiencing an issue with one VM. The job log begins at 21:30 and at 22:30
shows the first error.
2016-11-11T22:29:26.067+06:00 avvcbimage Info <16041>: VDDK:DISKLIB-LIB : numIOs = 2950000 numMergedIOs = 0 numSplitIOs = 0
2016-11-11T22:30:04.974+06:00 avvcbimage Info <16041>: VDDK:DISKLIB-LIB : numIOs = 3000000 numMergedIOs = 0 numSplitIOs = 0
2016-11-11T22:30:10.538+06:00 avvcbimage Info <40654>: isExitOK()=169
2016-11-11T22:30:10.538+06:00 avvcbimage Info <16022>: Cancel detected(externally cancelled by Administrator), isExitOK(0).
2016-11-11T22:30:10.538+06:00 avvcbimage Info <40654>: isExitOK()=169
2016-11-11T22:30:10.538+06:00 avvcbimage Info <16022>: Cancel detected(externally cancelled by Administrator), isExitOK(0).
2016-11-11T22:30:10.538+06:00 avvcbimage Info <9746>: bytes submitted was 197065048064
2016-11-11T22:30:10.540+06:00 avvcbimage Info <9772>: Starting graceful (staged) termination, MCS cancel (wrap-up stage)
2016-11-11T22:30:10.551+06:00 avvcbimage Info <19692>: Cancelled by MCS with timeout=0 sec
2016-11-11T22:30:10.635+06:00 avvcbimage Error <0000>: [IMG0010] pax_container::endfile(virtdisk-flat.vmdk,197065048064) returned problem:24
2016-11-11T22:30:10.638+06:00 avvcbimage Info <0000>: [IMG0010] pax_container::enddir returned problem:24
2016-11-11T22:30:10.638+06:00 avvcbimage Info <40654>: isExitOK()=169
2016-11-11T22:30:10.638+06:00 avvcbimage Info <16022>: Cancel detected(externally cancelled by Administrator), isExitOK(0).
2016-11-11T22:30:10.638+06:00 avvcbimage Info <12032>: backup ([Silverxxx] server-xxx/server-xxx_2.vmdk) terminated 307200.00 MB
2016-11-11T22:30:10.638+06:00 avvcbimage Info <40654>: isExitOK()=169
2016-11-11T22:30:10.638+06:00 avvcbimage Error <0000>: [IMG1003] Backup of [Silverxxx] server-xxx/server-xxx.vmdk failed
2016-11-11T22:30:10.650+06:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Close: Close disk.
2016-11-11T22:30:16.162+06:00 avvcbimage Info <6688>: Process 15025 (/usr/local/avamarclient/bin/avtar) finished (code 163: externally cancelled)
2016-11-11T22:30:16.162+06:00 avvcbimage Warning <6690>: CTL workorder "Servers xxx-Servers xxx-1478925000009" non-zero exit status 'code 163: externally cancelled'
2016-11-11T22:30:26.464+06:00 avvcbimage Info <9679>: Virtual disk connection to '[Silverxxx] server-xxx/server-xxx_2.vmdk' has been closed
2016-11-11T22:30:26.464+06:00 avvcbimage Info <40654>: isExitOK()=169
2016-11-11T22:30:26.464+06:00 avvcbimage Info <16022>: Cancel detected(externally cancelled by Administrator), isExitOK(0).
2016-11-11T22:30:26.464+06:00 avvcbimage Info <16052>: Terminating backup of all remaining virtual disks
2016-11-11T22:30:26.464+06:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Disconnect: Disconnect.
2016-11-11T22:30:26.487+06:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Cleanup: Remove previous mount points and clean up .
2016-11-11T22:30:26.487+06:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Connect: Establish connection.
2016-11-11T22:30:26.487+06:00 avvcbimage Info <16041>: VDDK:VixDiskLib: Resolve host.
2016-11-11T22:30:26.488+06:00 avvcbimage Info <16041>: VDDK:MemoryDbMappingsExpire: Expiring SSL ID mapping, hostname 192.168.0.xxx SSL ID 0d:d5:20:4d:8f:41:4c:f9:c5:ab:ff:2b:b0:e2:e7:18:dc:c7
2016-11-11T22:30:26.488+06:00 avvcbimage Info <16041>: VDDK:MemoryDbMappingsExpire: Expiring SSL ID mapping, hostname 192.168.1.xxx SSL ID 4e:89:f7:1d:b2:d4:81:96:b3:f4:04:20:56:a4:1d:ff:e4:a1
2016-11-11T22:30:26.703+06:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Disconnect: Disconnect.
2016-11-11T22:30:26.703+06:00 avvcbimage Info <9672>: Disconnected from VM
2016-11-11T22:30:26.703+06:00 avvcbimage Info <8701>: Closing pax stream
2016-11-11T22:30:26.730+06:00 avvcbimage Info <40645>: getActiveTaskCount prior to snapshot removal: CreateSnapshot=0 RemoveSnapshot=0 ImageTask=0 otherTask=0
2016-11-11T22:30:26.740+06:00 avvcbimage Info <41147>: no active snapshot removal tasks for vm moref 'vm-169'
2016-11-11T22:30:26.740+06:00 avvcbimage Info <14642>: Deleting the snapshot 'VDP-14789250258070daefa9130627093324fe5670a559235298f8', moref 'snapshot-1352'
2016-11-11T22:30:26.740+06:00 avvcbimage Info <0000>: SnapshotManager: deletesnapshot, snapshot-1352
2016-11-11T22:30:26.740+06:00 avvcbimage Info <0000>: SnapshotManager: POST to /snapshotmanager/snapshot/snapshot-1352/action/delete, payload({
"maxAttempts": -1})
2016-11-11T22:30:27.133+06:00 avvcbimage Info <0000>: AvSnapMgr::postData Succeeded
2016-11-11T22:30:27.133+06:00 avvcbimage Info <0000>: POST: curl_easy_getinfo - passed. HTTPCode: 202
2016-11-11T22:30:27.133+06:00 avvcbimage Info <0000>: AvSnapMgr::postData Succeeded
2016-11-11T22:30:27.133+06:00 avvcbimage Info <0000>: avSnapMgr::deleteSnapshot returned: HTTP/1.1 202 Accepted
Location: https://127.0.0.1:8543/snapshotmanager/task/task-8813
Content-Length: 0
Date: Sat, 12 Nov 2016 05:30:27 GMT
Connection: close
Server: Avamar
...
...
...
2016-11-11T21:30:46.003+06:00 avtar Info <5946>: File system character encoding is UTF-8.
2016-11-11T21:30:46.003+06:00 avtar Info <5588>: - Creating process lock file "/usr/local/avamarclient/var/VmImage7_avtar.lck", pid=15025
2016-11-11T21:30:46.004+06:00 avtar Info <8940>: Starting back up at 2016-11-11 21:30:46 MST as "root" on "dpxxx" (4 CPUs) [7.2.180-98]
2016-11-11T21:30:46.004+06:00 avtar Info <5731>: Not using include/exclude list
2016-11-11T21:30:46.004+06:00 avtar Info <8474>: - Log file path: Servers xxx-1478925000009-8070daefa9130627093324fe5670a559235298f8-3016-vmimagew_avtar.log
2016-11-11T21:30:46.004+06:00 avtar Info <6555>: Initializing connection
2016-11-11T21:30:46.004+06:00 avtar Info <5552>: Connecting to Avamar Server (dpxxx.xxx.corp)
2016-11-11T21:30:46.004+06:00 avtar Info <5554>: Connecting to one node in each datacenter
2016-11-11T21:30:46.040+06:00 avtar Info <5993>: - Connect: Connected to 192.168.1.160:29000, Priv=0, SSL Cipher=ECDHE-RSA-AES256-GCM-SHA384
2016-11-11T21:30:46.075+06:00 avtar Info <5993>: - Datacenter 0 has 1 nodes: Connected to 192.168.1.160:29000, Priv=0, SSL Cipher=ECDHE-RSA-AES256-GCM-SHA384
2016-11-11T21:30:46.080+06:00 avtar Info <5581>: Logging in on connection 0 with Session Ticket
2016-11-11T21:30:46.080+06:00 avtar Info <5582>: Avamar Server login successful
2016-11-11T21:30:46.080+06:00 avtar Info <5018>: - Session ID: 0
2016-11-11T21:30:46.083+06:00 avtar Info <10632>: Using Client-ID='8070daefa9130627093324fe5670a559235298f8'
2016-11-11T21:30:46.083+06:00 avtar Info <5550>: Successfully logged into Avamar Server [7.2.80-98] (Compression enabled)
2016-11-11T21:30:46.083+06:00 avtar Info <7562>: Back up of stdin on server "dpxxx.xxx.corp" for /vcxxx.xxx.corp/VirtualMachines/server-xxx_UB0KAkp4C8r7ismoqsJ0pw
2016-11-11T21:30:46.096+06:00 avtar Info <5586>: Loading cache files from /usr/local/avamarclient/var
2016-11-11T21:30:46.096+06:00 avtar Info <5769>: Filecache is disabled.
2016-11-11T21:30:46.096+06:00 avtar Info <8650>: Opening hash cache file '/usr/local/avamarclient/var/VmImage7_p_cache.dat'
2016-11-11T21:30:48.097+06:00 avtar Info <5573>: - Loaded hash cache file (25,166,368 bytes)
2016-11-11T21:30:48.218+06:00 avtar Info <6426>: Done loading cache files
2016-11-11T21:30:48.219+06:00 avtar Warning <18692>: Changed streamformat-out to none since raw format is only for DDR use
2016-11-11T21:30:48.219+06:00 avtar Info <6995>: Parsing 'pax' stream format from stdin
2016-11-11T21:30:48.219+06:00 avtar Info <10818>: Backstream creating root backstreamdir object
2016-11-11T21:30:48.219+06:00 avtar Info <8648>: Directory elements will be sorted: No
2016-11-11T21:30:48.219+06:00 avtar Info <8649>: Sub-file change blocks enabled: No
2016-11-11T21:45:47.229+06:00 avtar Info <8688>: Status 2016-11-11 21:45:47, 9 files, 84.77 GB (9 files, 87.32 MB, 0.10% new) 393MB 81% CPU 91026768896 input bytes, (1 open files) VMFiles/2/virtdisk-flat.vmdk
2016-11-11T22:00:49.034+06:00 avtar Info <8688>: Status 2016-11-11 22:00:49, 12 files, 192.7 GB (12 files, 88.32 MB, 0.04% new) 393MB 93% CPU 206948698112 input bytes, (1 open files) VMFiles/3/virtdisk-flat.vmdk
2016-11-11T22:13:08.645+06:00 avtar Info <5286>: 2016-11-11 22:13:08 MST: Increasing size of hash cache from 1048576 to 2097152 elements (adding 25,165,824 bytes).
2016-11-11T22:13:09.139+06:00 avtar Info <5069>: - Writing cache file "/usr/local/avamarclient/var/VmImage7_p_cache.dat"
2016-11-11T22:13:09.385+06:00 avtar Info <5546>: Cache update complete /usr/local/avamarclient/var/VmImage7_p_cache.dat (48.0 MiB of 618 MiB max)
2016-11-11T22:13:09.385+06:00 avtar Info <5122>: 2016-11-11 22:13:09 MST: Cache resize complete.
2016-11-11T22:15:50.037+06:00 avtar Info <8688>: Status 2016-11-11 22:15:50, 12 files, 260.0 GB (12 files, 88.33 MB, 0.03% new) 417MB 92% CPU 279142500352 input bytes, (1 open files) VMFiles/3/virtdisk-flat.vmdk
2016-11-11T22:30:10.584+06:00 avtar Info <7061>: Canceled by '3016-vmimagew' - exiting...
2016-11-11T22:30:10.620+06:00 avtar Info <9772>: Starting graceful (staged) termination, cancel request (wrap-up stage)
2016-11-11T22:30:15.703+06:00 [avtar] ERROR: <0001> backstreamdir::childdone error merging history stream data during phase_do_hidden while processing directory 'VMFiles/3'
2016-11-11T22:30:15.764+06:00 [avtar] ERROR: <0001> backstreamdir::childdone error merging history stream data during phase_do_hidden while processing directory 'VMFiles'
2016-11-11T22:30:15.833+06:00 avtar Info <7202>: Backup CANCELED, wrapping-up session with Server
2016-11-11T22:30:15.972+06:00 [avtar] ERROR: <0001> backstreamdir::childdone error merging history stream data during phase_do_hidden while processing directory ''
2016-11-11T22:30:16.028+06:00 avtar Info <7238>: Stream complete: 347,389,067,264 bytes read from stream
2016-11-11T22:30:16.029+06:00 avtar Info <5157>: PARTIAL Backup #51 timestamp 2016-11-11 22:30:16, 15 files, 5 directories, 323.5 GB (15 files, 88.66 MB, 0.03% new)
2016-11-11T22:30:16.029+06:00 avtar Info <7539>: Label "Servidores Pruebas-Servidores Pruebas-1478925000009", scheduled to expire after 11/18/16 (2016-11-19 05:30:16 UTC), daily backup, backup type: level0_full
2016-11-11T22:30:16.029+06:00 avtar Info <6083>: Backed-up 323.5 GB in 59.50 minutes: 326 GB/hour (15 files/hour)
2016-11-11T22:30:16.031+06:00 avtar Info <7883>: Finished at 2016-11-11 22:30:16 MST, Elapsed time: 0000h:59m:30s
2016-11-11T22:30:16.075+06:00 avtar Info <6149>: Error summary: 3 errors: 1(3)
2016-11-11T22:30:16.075+06:00 avtar Info <8468>: Sending wrapup message to parent
2016-11-11T22:30:16.077+06:00 avtar Info <5314>: Command failed (3 errors, 1 warning, exit code 10013: externally cancelled)
--------------------------------------------------------------------------------------------------------
----- END avtar log 2016-11-11 22:30:16 MST (1 warning, 3 erros, 0 fatal errors)
--------------------------------------------------------------------------------------------------------
When I google the error message It always shows something related to the backup duration more than a day but in this case it only takes 2 hours.
Regards,