cancel
Showing results for 
Search instead for 
Did you mean: 

Backup Job has a yellow man in activity monitor - not all files backed up

contra04
Level 5

Server 2003, netbackup 7.0

Backing up a server 2008 R2 server

The folder that is being backed up is 28 MB, and is a robocopy of the "data" directory.  I have a scheduled task that stops a service that has the files open. It then robocopies the directory into my Daily Backup folder. It then starts the service. This runs 30 minutes before the backup is due to start.  I am using the /B switch which sets the backup bit with robocopy - so that only newer files are copied into the folder that is too be backed up by netbackup.

 

 

 :: Stop the Services

NET STOP "Actuate 11 BIRT iServer"

timeout 60


SET _source=D:\Actuate\iServer\data


SET _dest=D:\Actuate\iServer\DailyBackup


SET _what=/COPYALL /B /SEC /MIR

:: /COPYALL :: COPY ALL file info

:: /B :: copy files in Backup mode

:: /SEC :: copy files with SECurity

:: /MIR :: MIRror a directory tree


SET _options=/R:0 /W:0 /LOG:D:\RWScripts\RoboCopyLog.txt /NFL /NDL

:: /R:n :: number of Retries

:: /W:n :: Wait time between retries

:: /LOG :: Output log file

:: /NFL :: No file logging

:: /NDL :: No dir logging


ROBOCOPY %_source% %_dest% %_what% %_options%


:: Start Services

NET START "Actuate 11 BIRT iServer" 
 
There is a monthly(full), weekly(full) and daily (cumulative incremental) that runs on this server.  The activity monitor always reports the YEllow man, that some files were in use and to examine the client logs. Which I have pasted below. 

ACtivity Monitor Job:

 

18/12/2011 03:37:34 - estimated 0 Kbytes needed
18/12/2011 03:37:35 - started process bpbrm (6224)
18/12/2011 03:37:40 - connecting
18/12/2011 03:37:44 - connected; connect time: 00:00:04
18/12/2011 03:37:48 - mounting CLU245
18/12/2011 03:38:37 - mounted; mount time: 00:00:49
18/12/2011 03:38:40 - positioning CLU245 to file 7
18/12/2011 03:39:27 - positioned CLU245; position time: 00:00:47
18/12/2011 03:39:27 - begin writing
18/12/2011 03:39:42 - end writing; write time: 00:00:15
the requested operation was successfully completed(0)
 
Activity Monitor "-":
8/12/2011 03:39:59 - ended process 0 (8880)

 

Status 0
18/12/2011 03:39:59 - end Snapshot, End Notify Script; elapsed time: 00:00:00
Status 1
18/12/2011 03:39:59 - end Parent Job; elapsed time: 00:03:33
the requested operation was partially successful(1)
 
The job was successfully completed, but some files may have been
busy or unaccessible. See the problems report or the client's logs for more details.

 

 
This is from the bpbkar log.
 
03:37:44.929: [3120.4856] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\121811.LOG
 
03:37:44.929: [3120.4856] <4> ov_log::OVInit: GENERAL Log Level: 0
03:37:44.929: [3120.4856] <4> ov_log::OVInit: TCP Log Level: 0
03:37:44.929: [3120.4856] <4> ov_log::OVInit: INF - the log mutex: 448
BPBKAR  NetBackup Backup/Archive  6.5GA  [Jan  4 2010]
Copyright 1993 - 2007 VERITAS Software Corporation
All Rights Reserved.
 
03:37:44.929: [3120.4856] <2> WinMain: DAT - _pgmptr = 'C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe'
03:37:44.929: [3120.4856] <2> WinMain: DAT - lpCmdLine = '-r 1814400 -ru root -dt 0 -to 0 -clnt Actuate-Lon -class Actuate-Lon -sched Full -st FULL -bpstart_to 600 -bpend_to 600 -read_to 3600 -stream_count 1 -stream_number 1 -jobgrpid 18133 -blks_per_buffer 128 -tir -tir_plus -use_otm -fso -Z -b Actuate-Lon_1324179454 -kl 28 -WOFB_enabled -WOFB_fim 0 -WOFB_usage 0 -WOFB_error 0 -ct 13 -use_ofb '
03:37:44.929: [3120.4856] <2> date_debug: DAT - timezone: GMT Standard Time, offset=0, dst: GMT Daylight Time
03:37:44.929: [3120.4856] <2> date_debug: DAT - current time: 1324179464, 18/12/2011 03:37:44
03:37:44.929: [3120.4856] <2> date_debug: DAT - 01/01/94 UCT:  757382400, 01/01/1994 00:00:00
03:37:44.929: [3120.4856] <2> date_debug: DAT - 07/01/94 UCT:  773020800, 01/07/1994 00:00:00
03:37:44.929: [3120.4856] <2> WinMain: DAT - standard input handle = 432
03:37:44.929: [3120.4856] <2> WinMain: DAT - standard output handle = 320
03:37:44.929: [3120.4856] <2> WinMain: DAT - standard error handle = 484
03:37:46.054: [3120.4856] <4> tar_backup::V_SetupJobData: INF - dwJobData: ffffffff
03:37:46.054: [3120.4856] <4> tar_backup::V_SetupJobData: INF -     dwJob: ffffffff
03:37:46.086: [3120.4856] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0
03:37:46.086: [3120.4856] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0
03:37:46.086: [3120.4856] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0
03:37:46.086: [3120.4856] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0
03:37:46.086: [3120.4856] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0
03:37:46.086: [3120.4856] <4> dos_backup::V_PreProcessing: INF - user name: root
03:37:46.086: [3120.4856] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup
03:37:46.086: [3120.4856] <2> ov_log::V_GlobalLog: ERR - ubsDetermineExchangeVersion():RegQueryValueEx() failed - 0x2.
03:37:46.086: [3120.4856] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0
03:37:46.117: [3120.4856] <2> ov_log::V_GlobalLog: INF - BEDS_Init() BEDS debgging will be enabled - dwDebugLevel = 0.
03:37:46.117: [3120.4856] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C:
03:37:46.117: [3120.4856] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: D:
03:37:46.117: [3120.4856] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Terminal Services
03:37:46.117: [3120.4856] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Windows Network
03:37:46.117: [3120.4856] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Shadow?Copy?Components
03:37:46.117: [3120.4856] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: System?State
03:37:46.117: [3120.4856] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Active Directory Application Mode
03:37:46.336: [3120.4856] <2> tar_backup::V_SetupProcessContinue: TAR - CONTINUE BACKUP received
03:37:46.554: [3120.4856] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = SET SNAP_ID=Actuate-Lon_1324179386
03:37:46.554: [3120.4856] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = BACKUP D:\Actuate\iServer\DailyBackup USING \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy5\Actuate\iServer\DailyBackup OPTIONS:ALT_PATH_PREFIX=C:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_3420,FITYPE=MIRROR,MNTPOINT=D:\,FSTYPE=NTFS
03:37:46.554: [3120.4856] <2> tar_base::V_vTarMsgW: INF - File data will be compressed when appropriate
03:37:46.554: [3120.4996] <4> tar_base::keepaliveThread: INF - keepalive thread is active with an interval of 60 seconds
03:37:46.679: [3120.4856] <2> tar_backup_vxbsa::add: INF - called with 'SET SNAP_ID=Actuate-Lon_1324179386'
03:37:46.679: [3120.4856] <2> tar_backup_vxbsa::add: INF - called with 'BACKUP D:\Actuate\iServer\DailyBackup USING \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy5\Actuate\iServer\DailyBackup OPTIONS:ALT_PATH_PREFIX=C:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_3420,FITYPE=MIRROR,MNTPOINT=D:\,FSTYPE=NTFS'
03:37:46.679: [3120.4856] <4> V_Snapshot::V_Snapshot_AddMappings: INF - Volume Snapshot Mapping: \\?\Volume{34db30ec-d562-11e0-af33-005056970054}\ --> GLOBALROOT\Device\HarddiskVolumeShadowCopy5
03:37:46.695: [3120.4856] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'D:\Actuate\iServer\DailyBackup' --> 10020002
03:37:47.742: [3120.4856] <4> backup_create: INF - NetBackup Temp Directory: 'C:\Program Files\Veritas\\NetBackup\Temp'
03:37:47.742: [3120.4856] <4> tar_backup_tfi::UpdateExcludeListWithVHD: INF - UpdateExludeListWithVHD begin
03:37:47.929: [3120.4856] <2> ov_log::V_GlobalLogEx: INF - file_access (constructor): 0 non-NTFS volumes
03:39:29.275: [3120.4856] <2> tar_base::backup_finish: TAR - backup:                     1092 files
03:39:29.275: [3120.4856] <2> tar_base::backup_finish: TAR - backup:    compressed data:   10200305 bytes
03:39:29.275: [3120.4856] <2> tar_base::backup_finish: TAR - backup:  uncompressed data:          0 bytes
03:39:29.275: [3120.4856] <2> tar_base::backup_finish: TAR - backup:          file data:   26429822 bytes
03:39:29.275: [3120.4856] <2> tar_base::backup_finish: TAR - backup:         image data:   13426688 bytes
03:39:29.275: [3120.4856] <2> tar_base::backup_finish: TAR - backup:       elapsed time:        102 secs       131634 bps
03:39:29.275: [3120.4856] <4> tar_backup::backup_done_state: INF - number of file directives not found: 0
03:39:29.275: [3120.4856] <4> tar_backup::backup_done_state: INF -     number of file directives found: 1
03:39:29.275: [3120.4996] <4> tar_base::keepaliveThread: INF - keepalive thread terminating (reason: WAIT_OBJECT_0)
03:39:29.275: [3120.4856] <4> tar_base::stopKeepaliveThread: INF - keepalive thread has exited. (reason: WAIT_OBJECT_0)
03:39:29.275: [3120.4856] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 0: the requested operation was successfully completed
03:39:40.275: [3120.4856] <4> dos_backup::tfs_reset: INF - Snapshot deletion start
03:39:40.275: [3120.4856] <4> OVStopCmd: INF - EXIT - status = 0
03:39:40.275: [3120.4856] <2> tar_base::V_Close: closing...
03:39:40.275: [3120.4856] <4> dos_backup::tfs_reset: INF - Snapshot deletion start
03:39:40.275: [3120.4856] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): enter - InitFlags:0x00000101
03:39:40.275: [3120.4856] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): ubs specifics: 0x001d0000
03:39:41.275: [3120.4856] <4> OVShutdown: INF - Finished process
03:39:41.275: [3120.4856] <4> WinMain: INF - Exiting C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe
03:39:43.275: [3120.4856] <4> ov_log::OVClose: INF - Closing log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\121811.LOG
 
I do not see anything that points to these files being in use?
Where would these be?
This folder is about to jump to 20 GB so I need to get this right before it goes live.
Could it be a problem with the /B switch in robocopy? Or are there really files in use?
1 ACCEPTED SOLUTION

Accepted Solutions

Mark_Solutions
Level 6
Partner Accredited Certified

Ok

So the only error i can see here is the BMR failure

As you are only backing up a single directory there is no point in collecting BMR data so de-select that from the attricbutes tab of the policy and then see if the job si 100% and a Blue Man - it should be from what i can see

After that you can look into your BMR issue (have you even set up BMR?) but that would be for another thread

View solution in original post

8 REPLIES 8

J_H_Is_gone
Level 6

Are there more than one child process to that parent job?

The child job you show has no error - but the Parent shows a 1 - so that makes me think there is more than one child process.

In activity monitor do a filter in the Parent Job ID column and see if you have more than one child job.

Mark_Solutions
Level 6
Partner Accredited Certified

If the parent shows an error of 1 you may have just selected the default to collect BMR data in the policy and the parent job only will show that the BMR collection failed - check its detailed status

If this is not the case then run a Problems report for the client and that should tell you what was skipped

contra04
Level 5

thank you for the suggestions chaps, there is only one child job, as there is only one directory being backed up.

How would I go about running a problems report?

Mark_Solutions
Level 6
Partner Accredited Certified

Contra04 ...

In the NetBackup Admin Console is a Reports section

One of the predefined reports is called Problems

Run this against just the client involved for the time period covering the backup time and see what you get

If it is BMR casuing it then the text will be in the detailed status of the Parent job, not the child - can you paste that in here for us to take a look

contra04
Level 5

Hi In the original post is both the parent detailed status, and the child detailed status.

 

 

The problem report contains two problems

BMERR: failed to connect via vnetd to bmr master daemon: cannot connect to socket (25) at 4:14 AM

and at 4:15 backup of client Actuate-Lon exited with status 1 (the requested operation was partially successful)

 

 

 21/12/2011 04:15:18 - ended process 0 (9576)

Status 0

21/12/2011 04:15:18 - end Snapshot, End Notify Script; elapsed time: 00:00:01

Status 1

21/12/2011 04:15:18 - end Parent Job; elapsed time: 00:01:59

the requested operation was partially successful(1)


The job was successfully completed, but some files may have been

busy or unaccessible. See the problems report or the client's logs for more details. 

 

And:

 

 21/12/2011 04:14:28 - estimated 2139 Kbytes needed

21/12/2011 04:14:29 - started process bpbrm (6680)

21/12/2011 04:14:34 - connecting

21/12/2011 04:14:37 - connected; connect time: 00:00:03

21/12/2011 04:14:44 - mounted

21/12/2011 04:14:44 - positioning LFT870 to file 144

21/12/2011 04:14:46 - positioned LFT870; position time: 00:00:02

21/12/2011 04:14:46 - begin writing

21/12/2011 04:15:00 - end writing; write time: 00:00:14

the requested operation was successfully completed(0) 

Mark_Solutions
Level 6
Partner Accredited Certified

Ok

So the only error i can see here is the BMR failure

As you are only backing up a single directory there is no point in collecting BMR data so de-select that from the attricbutes tab of the policy and then see if the job si 100% and a Blue Man - it should be from what i can see

After that you can look into your BMR issue (have you even set up BMR?) but that would be for another thread

contra04
Level 5

Thanks mark, your a champion.  No Bare metal restore tick, and I get the blue man group

Mark_Solutions
Level 6
Partner Accredited Certified

Great - glad to have helped - but have a look at your BMR setup anyway to see if it has an issue.