VMware Cloud Community
compupartes
Enthusiast
Enthusiast
‎11-14-2016 12:37 PM

Data Protection Fail job

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,

Tags (1)
0 Kudos
3 Replies
houssemghazouan
Contributor
Contributor
‎01-16-2022 01:10 PM

Good morning 

i have the same issue 

is there any updates 

 

best regards

0 Kudos
Naor91
Contributor
Contributor
‎05-03-2023 05:23 AM

Hello,

 

I have the same issue, i want it to know if you are some news about this kind of problem ?

 

Thanks in advance.

Regards.

0 Kudos
Lalegre
Virtuoso
Virtuoso
‎05-03-2023 05:55 AM

Hello @compupartes,

What version of vCenter and ESXi are you running? Also, please check if the backup job exceeds the backup window as that could be the reason for that error: https://docs.vmware.com/en/VMware-vSphere/6.5/vmware-data-protection-administration-guide-61.pdf (Page 57)

 

Tags (1)
0 Kudos