bppkar problem

[Vjeksa]

Hi,

i have problem on some servers with slow performance backup.

To avoid network issue, i've done test decscribed on article http://www.symantec.com/business/support/index?page=content&id=TECH17541

Bpbkar log show that that backup writing starts after 3 hours after backup has been initiated.

Any idea what could be the problem?

15:01:29.543 [9920.15188] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\041615.log

15:01:29.543 [9920.15188] <4> ov_log::OVInit: GENERAL Log Level (Effective): 0
15:01:29.543 [9920.15188] <4> ov_log::OVInit: TCP Log Level (Effective): 0
15:01:29.543 [9920.15188] <8> OVLog: BPBKAR  NetBackup Backup/Archive  7.6GA  [Oct 27 2014]

15:01:29.543 [9920.15188] <8> OVLog: Copyright © 1993 - 2014 Symantec Corporation, All Rights Reserved.
All Rights Reserved.

15:01:29.543 [9920.15188] <2> WinMain: BPBKAR_VERBOSE Debug log level: Actual=0, Effective=0
15:01:29.543 [9920.15188] <2> WinMain: DAT - _pgmptr = 'C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe'
15:01:29.543 [9920.15188] <2> WinMain: DAT - lpCmdLine = '-nocont c:\logs '
15:01:29.543 [9920.15188] <2> date_debug: DAT - timezone: Central European Standard Time, offset=-3600, dst: Central European Daylight Time
15:01:29.543 [9920.15188] <2> date_debug: DAT - current time: 1429189289, 16.4.2015. 15:01:29
15:01:29.543 [9920.15188] <2> date_debug: DAT - 01/01/94 UCT:  757382400, 1.1.1994. 1:00:00
15:01:29.543 [9920.15188] <2> date_debug: DAT - 07/01/94 UCT:  773020800, 1.7.1994. 2:00:00
15:01:29.543 [9920.15188] <2> WinMain: DAT - standard input handle = -2
15:01:29.543 [9920.15188] <4> WinMain: INF - not using socket for standard input handle
15:01:29.543 [9920.15188] <2> WinMain: DAT - standard output handle = 84
15:01:29.543 [9920.15188] <4> WinMain: INF - not using socket for standard output handle
15:01:29.543 [9920.15188] <2> WinMain: DAT - standard error handle = 80
15:01:29.543 [9920.15188] <4> WinMain: INF - not using socket for standard error handle
15:01:30.683 [9920.15188] <4> tar_backup::V_SetupJobData: INF - dwJobData: ffffffff
15:01:30.683 [9920.15188] <4> tar_backup::V_SetupJobData: INF -     dwJob: ffffffff
15:01:30.715 [9920.15188] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0
15:01:30.715 [9920.15188] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0
15:01:30.715 [9920.15188] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0
15:01:30.715 [9920.15188] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0
15:01:30.715 [9920.15188] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0
15:01:30.715 [9920.15188] <4> dos_backup::V_PreProcessing: INF - user name: 
15:01:30.715 [9920.15188] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup
15:01:30.715 [9920.15188] <2> ov_log::V_GlobalLog: WRN - ubsVerifyMIS():Microsoft Exchange Information Store is not installed.
15:01:30.715 [9920.15188] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0
15:01:30.762 [9920.15188] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C:
15:01:30.762 [9920.15188] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: EFI>System>Partition
15:01:30.762 [9920.15188] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Terminal Services
15:01:30.762 [9920.15188] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Windows Network
15:01:30.762 [9920.15188] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Web Client Network
15:01:30.762 [9920.15188] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: System?State
15:01:30.762 [9920.15188] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Active Directory Application Mode
15:01:30.777 [9920.15188] <2> tar_base::V_vTarMsgW: INF - BACKUP START 9920
15:01:30.777 [9920.15188] <2> tar_base::V_vTarMsgW: JBD - change time comparison:<disabled>
15:01:30.777 [9920.15188] <2> tar_base::V_vTarMsgW: JBD - archive bit processing:<enabled>
15:01:30.777 [9920.15188] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = c:\logs
15:01:30.777 [9920.12720] <4> tar_base::keepaliveThread: INF - keepalive thread is active with an interval of 30 seconds
15:01:30.902 [9920.15188] <2> tar_base::V_vTarMsgW: INF - Open File Backup license is not installed on the server.  Open File Backup usage will be disabled.
15:01:30.902 [9920.15188] <2> tar_backup_vxbsa::add: INF - called with 'c:\logs'
15:01:30.902 [9920.15188] <2> _expand_root: INF - checking for root expansion:<c:\logs>
15:01:30.902 [9920.15188] <2> _fix_registry: INF - checking for registry expansion:<c:\logs>
15:01:30.902 [9920.15188] <4> dos_backup::V_VerifyFileSystem: INF - corrected name:<C:\Logs>
15:01:30.902 [9920.15188] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'C:\Logs' --> 10020002
15:01:30.902 [9920.15188] <8> dos_backup::_change_journal_check: WRN - change journal not supported for schedule type:<>, file directive:<C:\Logs>, not allowing change journal usage
15:01:30.902 [9920.15188] <4> dos_backup::V_Initialize: INF - did not create change journal collection, not needed
18:05:43.855 [9920.15188] <4> backup_create: INF - NetBackup Temp Directory: 'C:\Program Files\Veritas\NetBackup\Temp'
18:05:43.855 [9920.15188] <4> tar_backup_tfi::backup_arg_state: INF - remember start error count: 0
18:05:43.855 [9920.15188] <4> tar_backup_tfi::backup_arg_state: INF - remember start fatal count: 0
18:05:43.855 [9920.15188] <4> dos_backup::tfs_scanstart: INF - starting scan for file directive:<C:\Logs>
18:05:43.855 [9920.15188] <4> dos_backup::tfs_scanstart: INF - starting scan using name:<C:\Logs>
18:05:43.855 [9920.15188] <4> dos_backup::tfs_scanstart: INF - in 'backup' mode
18:07:55.824 [9920.15188] <4> dos_backup::tfs_scannext: INF - no more path list entries
18:07:55.824 [9920.15188] <4> tar_backup::backup_endarg_state: INF - finish error count: 0
18:07:55.824 [9920.15188] <4> tar_backup::backup_endarg_state: INF - finish fatal count: 0
18:07:55.824 [9920.15188] <2> tar_base::backup_finish: TAR - backup:                     58 files
18:07:55.824 [9920.15188] <2> tar_base::backup_finish: TAR - backup:          file data:  867008462 bytes  3 gigabytes
18:07:55.824 [9920.15188] <2> tar_base::backup_finish: TAR - backup:         image data:  868581376 bytes  3 gigabytes
18:07:55.824 [9920.15188] <2> tar_base::backup_finish: TAR - backup:       elapsed time:        132 secs     30983385 bps
18:07:55.824 [9920.15188] <4> tar_backup::backup_done_state: INF - number of file directives not found: 0
18:07:55.824 [9920.15188] <4> tar_backup::backup_done_state: INF -     number of file directives found: 1
18:07:55.824 [9920.12720] <4> tar_base::keepaliveThread: INF - keepalive thread terminating (reason: WAIT_OBJECT_0)
18:07:55.824 [9920.15188] <4> tar_base::stopKeepaliveThread: INF - keepalive thread has exited. (reason: WAIT_OBJECT_0)
18:07:55.824 [9920.15188] <8> tar_backup_tfi::cleanupTemp: WRN - will not cleanup 'temp' directory, backup id or 'temp' directory is not set
18:07:55.824 [9920.15188] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 0: the requested operation was successfully completed
18:07:55.824 [9920.15188] <4> dos_backup::tfs_reset: INF - Snapshot deletion start
18:07:55.824 [9920.15188] <4> OVStopCmd: INF - EXIT - status = 0
18:07:55.824 [9920.15188] <2> tar_base::V_Close: closing...
18:07:55.824 [9920.15188] <4> dos_backup::tfs_reset: INF - Snapshot deletion start
18:07:55.824 [9920.15188] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): enter - InitFlags:0x00000101
18:07:55.824 [9920.15188] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): ubs specifics: 0x001d0000
18:07:55.824 [9920.15188] <4> OVShutdown: INF - Finished process
18:07:55.824 [9920.15188] <4> WinMain: INF - Exiting C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe

[revarooo]

you tried unticking Accelerator in the policy attributes then re-running the backup? The last message at 15:01 seems to imply the schedule type is not supported.

[Marianne]

Do you have bpfis log for the client?

Open File Backup is enabled by default, which means that Windows VSS needs to take a snapshot before the backup can start.

You should also increase logging level to a minimum of 3.
Not sufficient info in level 0 log.

[Vjeksa]

Syntax for this test was:
bpbkar32 -nocont [file_path_to_test] 1> nul 2> nul

Nothing to do with policy

[revarooo]

Ok in that case the log levels were too low

15:01:29.543 [9920.15188] <4> ov_log::OVInit: GENERAL Log Level (Effective): 0
15:01:29.543 [9920.15188] <4> ov_log::OVInit: TCP Log Level (Effective): 0

Increase them to maximum and re-run and post the bpbkar log.

Also let us know what the [file_path_to_test] is.

[GulzarShaikhAUS]

What version of Netbackup is on the client?

Also you can just turn off Open file backup and try the null backup test again. To disable WOFB you can go to master server host property->clients->add the client->deselect the open file backup option.

There might be issue with VSS on those servers? perhaps

[Vjeksa]

7.6.1 is client version

same error when WOFB is disabled

I've found VSS errors in win app log -

Event ID 8193

Volume Shadow Copy Service error: Unexpected error calling routine CreateVssExamineWriterMetadata.  hr = 0x80042302, A Volume Shadow Copy Service component encountered an unexpected error.
Check the Application event log for more information.
. 

Operation:
   Writer Exposing its Metadata

Context:
   Execution Context: Requestor
   Writer Instance ID: {1968EA26-D0A9-41D7-8A8A-DCFF9C850E62}
   Writer Class Id: {E8132975-6F93-4464-A53E-1050253AE220}
   Writer Name: System Writer

Volume Shadow Copy Service error: Unexpected error calling routine XML document is too long.  hr = 0x80070018, The program issued a command but the command length is incorrect.
. 

Operation:
   Writer Exposing its Metadata

Context:
   Execution Context: Requestor
   Writer Instance ID: {1968EA26-D0A9-41D7-8A8A-DCFF9C850E62}
   Writer Class Id: {E8132975-6F93-4464-A53E-1050253AE220}
   Writer Name: System Writer

[GulzarShaikhAUS]

If WOFB is disabled then we should not expect any events. Its strange.

Just to make sure can you please run following command on master server and recycle services on client.

  bpclient -client <client_name>  -add -WOFB_enabled 0

This time make sure you have bpbkar logging enabled and share the log.

[Marianne · Accepted solution]

WOFB is disabled in Master server Host Properties. So, this will have no effect when running bpbkar test on the client. You will probably need to reboot this client to get rid of VSS errors. If the errors return after the reboot, you will need to log a call with Microsoft or look for VSS hotfix.