09-03-2019 10:46 AM
We recently just upgraded from 7.7.2 to 8.1.2 and we have been experiencing this issue where some VMs in the policy will run and others will fail with 6 and 156.
VMs will flip flop with failure and succeed but all have this in its job details:
Sep 2, 2019 8:24:11 PM - Info nbjm (pid=49500) starting backup job (jobid=324433) for client xxxxxxx, policy VSPHERE_VMIP_DMZ_xxxxxxx, schedule Diff-Incr
Sep 2, 2019 8:24:11 PM - Info nbjm (pid=49500) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=324433, request id:{62E04202-A3F2-4555-BE68-5B2325894649})
Sep 2, 2019 8:24:11 PM - requesting resource DataDomain
Sep 2, 2019 8:24:11 PM - requesting resource xxxxxxxx.NBU_CLIENT.MAXJOBS.xxxxxx
Sep 2, 2019 8:24:11 PM - granted resource xxxxxxx.NBU_CLIENT.MAXJOBS.xxxxxxxxx
Sep 2, 2019 8:24:11 PM -granted resource MediaID=@aaaab;DiskVolume=xxxxxxxx;DiskPool=xxxxxxx;Path=xxxxxxxx;StorageServer=xxxxxdedupe;MediaServer=xxxxx
Sep 2, 2019 8:24:11 PM - granted resource xxxxxxx
Sep 2, 2019 8:24:11 PM - estimated 128863274 kbytes needed
Sep 2, 2019 8:24:11 PM - Info nbjm (pid=49500) started backup (backupid=xxxx_1567470251) job for client xxxxx, policy VSPHERE_VMIP_DMZ_xxxxx, schedule Diff-Incr on storage unit xxxxxx using backup host xxxxxxx
Sep 2, 2019 8:24:11 PM - started process bpbrm (pid=289432)
Sep 2, 2019 8:24:12 PM - Info bpbrm (pid=289432) xxxxxx is the host to backup data from
Sep 2, 2019 8:24:12 PM - Info bpbrm (pid=289432) reading file list for client
Sep 2, 2019 8:24:13 PM - Info bpbrm (pid=289432) accelerator enabled
Sep 2, 2019 8:24:16 PM - Info bpbrm (pid=289432) starting bpbkar32 on client
Sep 2, 2019 8:24:16 PM - connecting
Sep 2, 2019 8:24:16 PM - connected; connect time: 0:00:00
Sep 2, 2019 8:24:31 PM - Info bpbkar32 (pid=288800) Backup started
Sep 2, 2019 8:24:32 PM - Info bpbkar32 (pid=288800) accelerator enabled backup, archive bit processing:<disabled>
Sep 2, 2019 8:24:33 PM - Info bptm (pid=293528) start
Sep 2, 2019 8:24:33 PM - Info bptm (pid=293528) using 1048576 data buffer size
Sep 2, 2019 8:24:33 PM - Info bptm (pid=293528) setting receive network buffer to 4195328 bytes
Sep 2, 2019 8:24:33 PM - Info bptm (pid=293528) using 256 data buffers
Sep 2, 2019 8:24:36 PM - Info bptm (pid=293528) start backup
Sep 2, 2019 8:24:38 PM - begin writing
Sep 2, 2019 8:26:52 PM - Info bpbkar32 (pid=288800) INF - Backing up vCenter server xxxxxxx, ESX host xxxxxxxx, BIOS UUID sxxx, Instance UUID xxxxx, Display Name xxxxx, Hostname xxxxxxxxxx
Sep 2, 2019 8:28:20 PM - Info bpbkar32 (pid=288800) accelerator sent 0 bytes out of 0 bytes to server, optimization 0.0%
Sep 2, 2019 8:28:20 PM - Info bptm (pid=293528) waited for full buffer 1 times, delayed 14136 times
Sep 2, 2019 8:28:20 PM - Info bptm (pid=293528) EXITING with status 90 <----------
Sep 2, 2019 8:28:21 PM - Info bpbkar32 (pid=288800) bpbkar waited 0 times for empty buffer, delayed 0 times.
Sep 2, 2019 8:28:23 PM - Error bpbrm (pid=289432) could not send server status message to client
Sep 2, 2019 8:28:26 PM - Critical bpbrm (pid=289432) unexpected termination of client xxxxxxxxx
Sep 2, 2019 8:28:26 PM - Info bpbkar32 (pid=0) done. status: 6: the backup failed to back up the requested files
Sep 2, 2019 8:28:26 PM - end writing; write time: 0:03:48
User backup failed (6)
09-03-2019 01:00 PM
Investigate why bpbkar32 sent 0 bytes to bptm. Check the bpbkar log on the backup host. Is it reasonable for there to be nothing to back up (e.g., nothing new on an incremental backup)?
Status 90 (no data received) from bptm is consistent with bpbkar32 logging that it sent no data.
Investigate why bpbrm logged "could not send to client" and "unexpected termination of client." I suppose without proof that the client bpbrm referred to was bpbkar32 on the backup host. Had bpbkar32 exited by then? Did bpbkar32.exe crash?