cancel
Showing results for 
Search instead for 
Did you mean: 

Backup are failing

Kushaal
Level 4

Hi,

I had configured a BMR backup for Windows 2008 sever from netbackup 7.5.0.6 ,backup was running fine all these days.

From 2 days backup are failing with below error.kindly help in trobleshooting these issue

11/11/2013 9:00:19 PM - Info nbjm(pid=5312) starting backup job (jobid=915070) for client CHVBUVSAPP, policy Chennai_CHVBUVSAPP, schedule FULL  
11/11/2013 9:00:19 PM - estimated 804138562 Kbytes needed
11/11/2013 9:00:19 PM - Info nbjm(pid=5312) started backup (backupid=CHVBUVSAPP_1384183818) job for client CHVBUVSAPP, policy Chennai_CHVBUVSAPP, schedule FULL on storage unit chcitmsbkp02-hcart2-robot-tld-6
11/11/2013 9:00:20 PM - started process bpbrm (1600)
11/11/2013 9:00:29 PM - Info bpbrm(pid=1600) CHVBUVSAPP is the host to backup data from     
11/11/2013 9:00:29 PM - Info bpbrm(pid=1600) reading file list from client        
11/11/2013 9:00:29 PM - connecting
11/11/2013 9:00:32 PM - Info bpbrm(pid=1600) starting bpbkar32 on client         
11/11/2013 9:00:32 PM - connected; connect time: 00:00:03
11/11/2013 9:00:42 PM - Info bpbkar32(pid=6032) Backup started           
11/11/2013 9:00:42 PM - Info bptm(pid=3276) start            
11/11/2013 9:00:43 PM - Info bptm(pid=3276) using 65536 data buffer size        
11/11/2013 9:00:43 PM - Info bptm(pid=3276) setting receive network buffer to 263168 bytes      
11/11/2013 9:00:43 PM - Info bptm(pid=3276) using 30 data buffers         
11/11/2013 9:00:43 PM - Info bptm(pid=3276) start backup           
11/11/2013 9:00:43 PM - Info bptm(pid=3276) backup child process is pid 4620.5944       
11/11/2013 9:00:43 PM - Info bptm(pid=3276) Waiting for mount of media id 000053 (copy 1) on server chcitmsbkp02.lntcorp.lntuniverse.com. 
11/11/2013 9:00:43 PM - mounting 000053
11/11/2013 9:00:44 PM - Info bptm(pid=4620) start            
11/11/2013 9:01:16 PM - Error bpbrm(pid=1600) from client CHVBUVSAPP: ERR - Volume resolution error for (System State:\System Files\System Files)
11/11/2013 9:01:17 PM - Error bpbrm(pid=1600) cannot send mail     
11/11/2013 9:01:18 PM - Info bpbkar32(pid=6032) done. status: 156: snapshot error encountered       
11/11/2013 9:01:18 PM - end writing
snapshot error encountered(156)
8 REPLIES 8

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

Is this a node in a cluster?

Did the cluster maybe failover recently, making this node the inactive node?

If so, see http://www.symantec.com/docs/TECH199089

Kushaal
Level 4

Hi Marianne van den berg,

NO failover of cluster has happend.
1)our master server is in cluster

2)I am managing backup through one Media server in our backup environment  taking Netbackup Administration console 

3)Other policy backuped up through this  media server is running fine and is succesfull,

only policy BY name Chennai_CHVBUVSAPP is failing it has client name CHVBUVSAPP

 

Where CHVBUVSAP is a windows 2008 server for which BMR backup is configured .

Kushaal
Level 4

backup are failing with error mentioned above

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

I am referring to clustered clients. 

Have you had a look at the TN in my post above?

If this is not your issue, you will need logs on the client to troubleshoot:
bpfis and bpbkar.
Increase logging level to 3 on the client.

Kushaal
Level 4

HI Marianne van den Berg,

Bfis logs 

17:57:47.414 [4840.7448] <2> logparams: bpfis query -id CHVBUVSAPP_1384345645 -copy 1 
17:57:47.474 [4840.7448] <4> bpfis: Starting keep alive thread.
17:57:47.496 [4840.7448] <8> file_to_cache_item: [vnet_addrinfo.c:6555] fopen() failed ERRNO=2 FILE=C:\Program Files\Veritas\NetBackup\var\host_cache\07f\dacfe87f+bprd,1,400,2,1,0+citbknbu02.lntcorp.lntuniverse.com.txt
17:57:47.604 [4840.7448] <2> vnet_pbxConnect: pbxConnectEx Succeeded
17:57:47.604 [4840.7448] <2> logconnections: BPRD CONNECT FROM 192.168.223.140.50615 TO 192.168.70.94.1556 fd = 504
17:57:47.629 [4840.7448] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
17:57:52.224 [4840.7448] <4> bpfis: INF - BACKUP START 4840
17:57:52.225 [4840.7448] <32> bpfis: FTL - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.CHVBUVSAPP_1384345645.1.0
17:57:52.225 [4840.7448] <4> bpfis main: Overriding original online_util() status <12> with <1542>.
17:57:52.225 [4840.7448] <4> bpfis: Starting keep alive thread.
17:57:52.225 [4840.7448] <4> bpfis: INF - EXIT STATUS 1542: An existing snapshot is no longer valid and cannot be mounted for subsequent operations
17:59:56.896 [6628.3940] <2> logparams: bpfis query -id CHVBUVSAPP_1384345776 -copy 1 
17:59:56.897 [6628.3940] <4> bpfis: Starting keep alive thread.
17:59:56.986 [6628.3940] <2> vnet_pbxConnect: pbxConnectEx Succeeded
17:59:56.987 [6628.3940] <2> logconnections: BPRD CONNECT FROM 192.168.223.140.51179 TO 192.168.70.94.1556 fd = 500
17:59:56.987 [6628.3940] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
18:00:01.595 [6628.3940] <4> bpfis: INF - BACKUP START 6628
18:00:01.595 [6628.3940] <32> bpfis: FTL - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.CHVBUVSAPP_1384345776.1.0
18:00:01.595 [6628.3940] <4> bpfis main: Overriding original online_util() status <12> with <1542>.
18:00:01.596 [6628.3940] <4> bpfis: Starting keep alive thread.
18:00:01.596 [6628.3940] <4> bpfis: INF - EXIT STATUS 1542: An existing snapshot is no longer valid and cannot be mounted for subsequent operations
 
Bpbkar logs
 
5:57:40.471 PM: [7828.3148] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\111313.LOG
 
5:57:40.471 PM: [7828.3148] <4> ov_log::OVInit: GENERAL Log Level: 0
5:57:40.471 PM: [7828.3148] <4> ov_log::OVInit: TCP Log Level: 0
5:57:40.471 PM: [7828.3148] <4> ov_log::OVInit: INF - the log mutex: 340
BPBKAR  NetBackup Backup/Archive  7.5GA  [Jun  5 2012]
Copyright © 1993 - 2012 Symantec Corporation, All Rights Reserved.
All Rights Reserved.
 
5:57:40.474 PM: [7828.3148] <2> WinMain: DAT - _pgmptr = 'C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe'
5:57:40.474 PM: [7828.3148] <2> WinMain: DAT - lpCmdLine = '-r 1209600 -ru root -dt 0 -to 0 -bpstart_time 1384345945 -clnt CHVBUVSAPP -class Chennai_CHVBUVSAPP -sched FULL -st FULL -bpstart_to 300 -bpend_to 300 -read_to 300 -ckpt_time 2700 -blks_per_buffer 128 -tir -tir_plus -use_otm -fso -b CHVBUVSAPP_1384345645 -kl 28 -WOFB_enabled -WOFB_fim 0 -WOFB_usage 0 -WOFB_error 0 -ct 13 -use_ofb '
5:57:40.474 PM: [7828.3148] <2> date_debug: DAT - timezone: India Standard Time, offset=-19800, dst: NONE
5:57:40.474 PM: [7828.3148] <2> date_debug: DAT - current time: 1384345660, 11/13/2013 5:57:40 PM
5:57:40.474 PM: [7828.3148] <2> date_debug: DAT - 01/01/94 UCT:  757382400, 1/1/1994 5:30:00 AM
5:57:40.474 PM: [7828.3148] <2> date_debug: DAT - 07/01/94 UCT:  773020800, 7/1/1994 5:30:00 AM
5:57:40.474 PM: [7828.3148] <2> WinMain: DAT - standard input handle = 356
5:57:40.478 PM: [7828.3148] <2> WinMain: DAT - standard input handle is NOT resilient socket.
5:57:40.478 PM: [7828.3148] <2> WinMain: DAT - standard output handle = 204
5:57:40.478 PM: [7828.3148] <2> WinMain: DAT - standard output handle is NOT resilient socket.
5:57:40.478 PM: [7828.3148] <2> WinMain: DAT - standard error handle = 324
5:57:40.478 PM: [7828.3148] <2> WinMain: DAT - standard error handle is NOT resilient socket.
5:57:40.629 PM: [7828.3148] <4> tar_backup_tfi::create: INF - change time comparison:<disabled>
5:57:40.730 PM: [7828.3148] <4> tar_backup::V_SetupJobData: INF - dwJobData: 00000000
5:57:40.730 PM: [7828.3148] <4> tar_backup::V_SetupJobData: INF -     dwJob: 00000000
5:57:40.770 PM: [7828.3148] <4> ncfLogConfiguration: INF - Module: libncf, Release: 7.5.0.3 , Build: 06/05/2012 20:00:00 CDT (20120605)
5:57:40.776 PM: [7828.3148] <4> ncfLogConfiguration: INF - Windows version: 6.0.6002, Platform: 2 (Service Pack 2), Service pack: 2.0, Suite: 272, Product type: 3
5:57:40.783 PM: [7828.3148] <4> ncfLogConfiguration: INF - Process architecture: 0, Page size: 4096, Process type: 1, Process level: 586, Processor revision: 6
5:57:40.790 PM: [7828.3148] <4> NcfString::logLocale: INF - Current code page: WINDOWS: 1252  (ANSI - Latin I), Max. character width: 1, Substitution character: 0x3F [?], Unicode substitution character: 0x003f [?.]
5:57:40.791 PM: [7828.3148] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0
5:57:40.791 PM: [7828.3148] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0
5:57:40.792 PM: [7828.3148] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0
5:57:40.792 PM: [7828.3148] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0
5:57:40.792 PM: [7828.3148] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0
5:57:40.792 PM: [7828.3148] <4> dos_backup::V_PreProcessing: INF - user name: root
5:57:40.792 PM: [7828.3148] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup
5:57:40.793 PM: [7828.3148] <2> ov_log::V_GlobalLog: WRN - ubsDetermineExchangeVersion(): RegOpenKeyEx() failed for HKLM\SOFTWARE\MICROSOFT\ExchangeServer\v14\Setup - 0x2.
5:57:40.800 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0
5:57:44.057 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C:
5:57:44.058 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: D:
5:57:44.058 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Terminal Services
5:57:44.058 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Windows Network
5:57:44.058 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Symantec SNAC Network Provider
5:57:44.058 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: CHVBUVSAPP\Microsoft SQL Server Instances
5:57:44.058 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - DumpChildDleInfo() Child DLE Device Name: CHVBUVSAPP\MSSQLSERVER
5:57:44.058 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: System?State
5:57:44.058 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Active Directory Application Mode
5:57:44.102 PM: [7828.3148] <2> tar_base::V_vTarMsgW: INF - BACKUP START 7828
5:57:44.303 PM: [7828.3148] <2> tar_backup::V_SetupProcessContinue: TAR - CONTINUE BACKUP received
5:57:44.303 PM: [7828.3148] <2> tar_base::V_vTarMsgW: INF - CONTINUE BACKUP message received
5:57:44.303 PM: [7828.3148] <4> tar_backup_cpr::start: INF - checkpoint thread started
5:57:44.494 PM: [7828.3148] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = ALL_LOCAL_DRIVES
5:57:44.494 PM: [7828.7320] <4> tar_base::keepaliveThread: INF - keepalive thread is active with an interval of 60 seconds
5:57:45.529 PM: [7828.3148] <2> NBJournalDataCollection::NBJournalDataCollection: INF - volume guid:<\\?\Volume{8b76f79f-ac69-11e1-b75c-806e6f6e6963}\>
5:57:45.529 PM: [7828.3148] <2> NBJournalDataCollection::NBJournalDataCollection: INF - mounted at:<C:\>:<\\?\Volume{8b76f79f-ac69-11e1-b75c-806e6f6e6963}\>
5:57:45.529 PM: [7828.3148] <2> NBJournalDataCollection::NBJournalDataCollection: INF - not adding to collection, volume:<\\?\Volume{8b76f79f-ac69-11e1-b75c-806e6f6e6963}\>:<C:\> is configured to not use the change journal
5:57:45.529 PM: [7828.3148] <2> NBJournalDataCollection::NBJournalDataCollection: INF - volume guid:<\\?\Volume{abba26b4-ae04-11e1-8e17-00155ddf6505}\>
5:57:45.529 PM: [7828.3148] <2> NBJournalDataCollection::NBJournalDataCollection: INF - mounted at:<D:\>:<\\?\Volume{abba26b4-ae04-11e1-8e17-00155ddf6505}\>
5:57:45.529 PM: [7828.3148] <2> NBJournalDataCollection::NBJournalDataCollection: INF - not adding to collection, volume:<\\?\Volume{abba26b4-ae04-11e1-8e17-00155ddf6505}\>:<D:\> is configured to not use the change journal
5:57:45.529 PM: [7828.3148] <4> dos_backup::V_Initialize: INF - created change journal collection
5:57:45.529 PM: [7828.3148] <4> V_Snapshot::V_Snapshot_Query: INF - Attempting to query volume snapshots: bpfis query -id CHVBUVSAPP_1384345645  -copy 1
5:57:52.685 PM: [7828.3148] <4> V_Snapshot::V_Snapshot_ParseBpfisOutput: INF - Snapshot creation, FIS_ID: CHVBUVSAPP_1384345645
5:57:52.685 PM: [7828.3148] <2> tar_backup_vxbsa::add: INF - called with '/'
5:57:52.685 PM: [7828.3148] <2> _expand_root: INF - checking for root expansion:<:\>
5:57:52.685 PM: [7828.3148] <2> _expand_root: INF - Added: C:\
5:57:52.685 PM: [7828.3148] <2> _expand_root: INF - Added: D:\
5:57:52.685 PM: [7828.3148] <2> _expand_root: INF - Added: Shadow Copy Components:\
5:57:52.685 PM: [7828.3148] <2> _expand_root: INF - Added: System State:\
5:57:52.685 PM: [7828.3148] <2> _expand_root: INF - checking for root expansion:<C:\>
5:57:52.685 PM: [7828.3148] <2> _expand_root: INF - checking for root expansion:<D:\>
5:57:52.685 PM: [7828.3148] <2> _expand_root: INF - checking for root expansion:<Shadow Copy Components:\>
5:57:52.685 PM: [7828.3148] <2> _expand_root: INF - checking for root expansion:<System State:\>
5:57:52.685 PM: [7828.3148] <2> _fix_registry: INF - checking for registry expansion:<C:\>
5:57:52.685 PM: [7828.3148] <2> _fix_registry: INF - checking for registry expansion:<D:\>
5:57:52.685 PM: [7828.3148] <2> _fix_registry: INF - checking for registry expansion:<Shadow Copy Components:\>
5:57:52.685 PM: [7828.3148] <2> _fix_registry: INF - checking for registry expansion:<System State:\>
5:57:52.685 PM: [7828.3148] <2> _validate_change_journal_use: ERR - change journal not supported for <Shadow Copy Components:\>,  prevent change journal usage
5:57:52.685 PM: [7828.3148] <2> _validate_change_journal_use: ERR - change journal not supported for <System State:\>,  prevent change journal usage
5:57:52.724 PM: [7828.3148] <4> dos_backup::V_VerifyFileSystem: INF - corrected name:<C:\>
5:57:52.724 PM: [7828.3148] <4> dos_backup::V_VerifyFileSystem: INF - corrected name:<D:\>
5:57:52.724 PM: [7828.3148] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'C:\' --> 10020002
5:57:52.725 PM: [7828.3148] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'D:\' --> 10020002
5:57:59.863 PM: [7828.3148] <4> dos_backup::V_VerifyFileList: INF - Hidden Device, Ignoring filelist entry for 'Shadow Copy Components:\'
5:57:59.863 PM: [7828.3148] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'Shadow Copy Components:\' --> 10020027
5:58:01.859 PM: [7828.3148] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'System State:\' --> 1002002d
5:58:01.859 PM: [7828.3148] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for '_BACKUP_SPECIAL_OBJECTS AFTER System State:' --> 1002002d
5:58:03.852 PM: [7828.3148] <4> VssSnapshot::V_VssSetMetadata(): INF - Unable to locate DFSR metadata
5:58:05.505 PM: [7828.3148] <4> dos_backup::tfs_scanstart: INF - starting scan for file directive:<System State:\>
5:58:05.505 PM: [7828.3148] <4> dos_backup::tfs_scanstart: INF - starting scan using name:<System State:\>
5:58:05.505 PM: [7828.3148] <4> dos_backup::tfs_scanstart: INF - in 'pre-backup' mode
5:58:06.166 PM: [7828.3148] <16> dos_backup::V_InitializeSystemState: ERR - FS_AddToSnapshotSet() Failed! (System State:\System Files\System Files) $s
5:58:06.166 PM: [7828.3148] <2> tar_base::V_vTarMsgW: ERR - Volume resolution error for (System State:\System Files\System Files)
5:58:06.177 PM: [7828.3148] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 156: snapshot error encountered
5:58:06.177 PM: [7828.3148] <4> backup_create: INF - NetBackup Temp Directory: 'C:\Program Files\Veritas\\NetBackup\Temp'
5:58:06.178 PM: [7828.3148] <4> tar_backup_tfi::UpdateExcludeListWithVHD: INF - UpdateExludeListWithVHD begin
5:58:08.337 PM: [7828.3148] <4> OVStopCmd: INF - EXIT - status = 0
5:58:08.337 PM: [7828.3148] <2> tar_base::V_Close: closing...
5:58:09.388 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): enter - InitFlags:0x00000101
5:58:09.388 PM: [7828.3148] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): ubs specifics: 0x001d0000
5:58:09.405 PM: [7828.7320] <4> tar_base::keepaliveThread: INF - keepalive thread terminating (reason: WAIT_OBJECT_0)
5:58:09.405 PM: [7828.3148] <4> tar_base::stopKeepaliveThread: INF - keepalive thread has exited. (reason: WAIT_OBJECT_0)
5:58:09.405 PM: [7828.3148] <16> dtcp_read: TCP - failure: recv socket (356) (TCP 10053: Software caused connection abort)
5:58:09.405 PM: [7828.3148] <4> OVShutdown: INF - Finished process
5:58:09.407 PM: [7828.3148] <4> WinMain: INF - Exiting C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe
5:58:11.407 PM: [7828.3148] <4> ov_log::OVClose: INF - Closing log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\111313.LOG
 
5:59:48.500 PM: [3588.7308] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\111313.LOG
 
5:59:48.500 PM: [3588.7308] <4> ov_log::OVInit: GENERAL Log Level: 0
5:59:48.500 PM: [3588.7308] <4> ov_log::OVInit: TCP Log Level: 0
5:59:48.500 PM: [3588.7308] <4> ov_log::OVInit: INF - the log mutex: 340
BPBKAR  NetBackup Backup/Archive  7.5GA  [Jun  5 2012]
Copyright © 1993 - 2012 Symantec Corporation, All Rights Reserved.
All Rights Reserved.
 
5:59:48.534 PM: [3588.7308] <2> WinMain: DAT - _pgmptr = 'C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe'
5:59:48.534 PM: [3588.7308] <2> WinMain: DAT - lpCmdLine = '-r 1209600 -ru root -dt 0 -to 0 -bpstart_time 1384346077 -clnt CHVBUVSAPP -class Chennai_CHVBUVSAPP -sched FULL -st FULL -bpstart_to 300 -bpend_to 300 -read_to 300 -ckpt_time 2700 -blks_per_buffer 128 -tir -tir_plus -use_otm -fso -b CHVBUVSAPP_1384345776 -kl 28 -WOFB_enabled -WOFB_fim 0 -WOFB_usage 0 -WOFB_error 0 -ct 13 -use_ofb '
5:59:48.535 PM: [3588.7308] <2> date_debug: DAT - timezone: India Standard Time, offset=-19800, dst: NONE
5:59:48.535 PM: [3588.7308] <2> date_debug: DAT - current time: 1384345788, 11/13/2013 5:59:48 PM
5:59:48.535 PM: [3588.7308] <2> date_debug: DAT - 01/01/94 UCT:  757382400, 1/1/1994 5:30:00 AM
5:59:48.535 PM: [3588.7308] <2> date_debug: DAT - 07/01/94 UCT:  773020800, 7/1/1994 5:30:00 AM
5:59:48.535 PM: [3588.7308] <2> WinMain: DAT - standard input handle = 356
5:59:48.539 PM: [3588.7308] <2> WinMain: DAT - standard input handle is NOT resilient socket.
5:59:48.539 PM: [3588.7308] <2> WinMain: DAT - standard output handle = 204
5:59:48.539 PM: [3588.7308] <2> WinMain: DAT - standard output handle is NOT resilient socket.
5:59:48.539 PM: [3588.7308] <2> WinMain: DAT - standard error handle = 324
5:59:48.539 PM: [3588.7308] <2> WinMain: DAT - standard error handle is NOT resilient socket.
5:59:48.541 PM: [3588.7308] <4> tar_backup_tfi::create: INF - change time comparison:<disabled>
5:59:48.644 PM: [3588.7308] <4> tar_backup::V_SetupJobData: INF - dwJobData: 00000000
5:59:48.644 PM: [3588.7308] <4> tar_backup::V_SetupJobData: INF -     dwJob: 00000001
5:59:48.669 PM: [3588.7308] <4> ncfLogConfiguration: INF - Module: libncf, Release: 7.5.0.3 , Build: 06/05/2012 20:00:00 CDT (20120605)
5:59:48.676 PM: [3588.7308] <4> ncfLogConfiguration: INF - Windows version: 6.0.6002, Platform: 2 (Service Pack 2), Service pack: 2.0, Suite: 272, Product type: 3
5:59:48.683 PM: [3588.7308] <4> ncfLogConfiguration: INF - Process architecture: 0, Page size: 4096, Process type: 1, Process level: 586, Processor revision: 6
5:59:48.690 PM: [3588.7308] <4> NcfString::logLocale: INF - Current code page: WINDOWS: 1252  (ANSI - Latin I), Max. character width: 1, Substitution character: 0x3F [?], Unicode substitution character: 0x003f [?.]
5:59:48.691 PM: [3588.7308] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0
5:59:48.691 PM: [3588.7308] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0
5:59:48.692 PM: [3588.7308] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0
5:59:48.692 PM: [3588.7308] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0
5:59:48.692 PM: [3588.7308] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0
5:59:48.692 PM: [3588.7308] <4> dos_backup::V_PreProcessing: INF - user name: root
5:59:48.692 PM: [3588.7308] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup
5:59:48.693 PM: [3588.7308] <2> ov_log::V_GlobalLog: WRN - ubsDetermineExchangeVersion(): RegOpenKeyEx() failed for HKLM\SOFTWARE\MICROSOFT\ExchangeServer\v14\Setup - 0x2.
5:59:48.694 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0
5:59:48.800 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C:
5:59:48.800 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: D:
5:59:48.800 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Terminal Services
5:59:48.800 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Windows Network
5:59:48.800 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Symantec SNAC Network Provider
5:59:48.800 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: CHVBUVSAPP\Microsoft SQL Server Instances
5:59:48.800 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - DumpChildDleInfo() Child DLE Device Name: CHVBUVSAPP\MSSQLSERVER
5:59:48.800 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: System?State
5:59:48.800 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Active Directory Application Mode
5:59:48.819 PM: [3588.7308] <2> tar_base::V_vTarMsgW: INF - BACKUP START 3588
5:59:49.031 PM: [3588.7308] <2> tar_backup::V_SetupProcessContinue: TAR - CONTINUE BACKUP received
5:59:49.031 PM: [3588.7308] <2> tar_base::V_vTarMsgW: INF - CONTINUE BACKUP message received
5:59:49.031 PM: [3588.7308] <4> tar_backup_cpr::start: INF - checkpoint thread started
5:59:49.233 PM: [3588.7308] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = ALL_LOCAL_DRIVES
5:59:49.233 PM: [3588.5108] <4> tar_base::keepaliveThread: INF - keepalive thread is active with an interval of 60 seconds
5:59:50.286 PM: [3588.7308] <2> NBJournalDataCollection::NBJournalDataCollection: INF - volume guid:<\\?\Volume{8b76f79f-ac69-11e1-b75c-806e6f6e6963}\>
5:59:50.286 PM: [3588.7308] <2> NBJournalDataCollection::NBJournalDataCollection: INF - mounted at:<C:\>:<\\?\Volume{8b76f79f-ac69-11e1-b75c-806e6f6e6963}\>
5:59:50.286 PM: [3588.7308] <2> NBJournalDataCollection::NBJournalDataCollection: INF - not adding to collection, volume:<\\?\Volume{8b76f79f-ac69-11e1-b75c-806e6f6e6963}\>:<C:\> is configured to not use the change journal
5:59:50.286 PM: [3588.7308] <2> NBJournalDataCollection::NBJournalDataCollection: INF - volume guid:<\\?\Volume{abba26b4-ae04-11e1-8e17-00155ddf6505}\>
5:59:50.286 PM: [3588.7308] <2> NBJournalDataCollection::NBJournalDataCollection: INF - mounted at:<D:\>:<\\?\Volume{abba26b4-ae04-11e1-8e17-00155ddf6505}\>
5:59:50.286 PM: [3588.7308] <2> NBJournalDataCollection::NBJournalDataCollection: INF - not adding to collection, volume:<\\?\Volume{abba26b4-ae04-11e1-8e17-00155ddf6505}\>:<D:\> is configured to not use the change journal
5:59:50.286 PM: [3588.7308] <4> dos_backup::V_Initialize: INF - created change journal collection
5:59:50.286 PM: [3588.7308] <4> V_Snapshot::V_Snapshot_Query: INF - Attempting to query volume snapshots: bpfis query -id CHVBUVSAPP_1384345776  -copy 1
6:00:02.360 PM: [3588.7308] <4> V_Snapshot::V_Snapshot_ParseBpfisOutput: INF - Snapshot creation, FIS_ID: CHVBUVSAPP_1384345776
6:00:02.360 PM: [3588.7308] <2> tar_backup_vxbsa::add: INF - called with '/'
6:00:02.360 PM: [3588.7308] <2> _expand_root: INF - checking for root expansion:<:\>
6:00:02.360 PM: [3588.7308] <2> _expand_root: INF - Added: C:\
6:00:02.360 PM: [3588.7308] <2> _expand_root: INF - Added: D:\
6:00:02.360 PM: [3588.7308] <2> _expand_root: INF - Added: Shadow Copy Components:\
6:00:02.360 PM: [3588.7308] <2> _expand_root: INF - Added: System State:\
6:00:02.360 PM: [3588.7308] <2> _expand_root: INF - checking for root expansion:<C:\>
6:00:02.360 PM: [3588.7308] <2> _expand_root: INF - checking for root expansion:<D:\>
6:00:02.360 PM: [3588.7308] <2> _expand_root: INF - checking for root expansion:<Shadow Copy Components:\>
6:00:02.360 PM: [3588.7308] <2> _expand_root: INF - checking for root expansion:<System State:\>
6:00:02.360 PM: [3588.7308] <2> _fix_registry: INF - checking for registry expansion:<C:\>
6:00:02.360 PM: [3588.7308] <2> _fix_registry: INF - checking for registry expansion:<D:\>
6:00:02.360 PM: [3588.7308] <2> _fix_registry: INF - checking for registry expansion:<Shadow Copy Components:\>
6:00:02.360 PM: [3588.7308] <2> _fix_registry: INF - checking for registry expansion:<System State:\>
6:00:02.360 PM: [3588.7308] <2> _validate_change_journal_use: ERR - change journal not supported for <Shadow Copy Components:\>,  prevent change journal usage
6:00:02.360 PM: [3588.7308] <2> _validate_change_journal_use: ERR - change journal not supported for <System State:\>,  prevent change journal usage
6:00:02.390 PM: [3588.7308] <4> dos_backup::V_VerifyFileSystem: INF - corrected name:<C:\>
6:00:02.390 PM: [3588.7308] <4> dos_backup::V_VerifyFileSystem: INF - corrected name:<D:\>
6:00:02.391 PM: [3588.7308] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'C:\' --> 10020002
6:00:02.391 PM: [3588.7308] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'D:\' --> 10020002
6:00:04.292 PM: [3588.7308] <4> dos_backup::V_VerifyFileList: INF - Hidden Device, Ignoring filelist entry for 'Shadow Copy Components:\'
6:00:04.292 PM: [3588.7308] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'Shadow Copy Components:\' --> 10020027
6:00:06.231 PM: [3588.7308] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'System State:\' --> 1002002d
6:00:06.231 PM: [3588.7308] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for '_BACKUP_SPECIAL_OBJECTS AFTER System State:' --> 1002002d
6:00:08.151 PM: [3588.7308] <4> VssSnapshot::V_VssSetMetadata(): INF - Unable to locate DFSR metadata
6:00:09.624 PM: [3588.7308] <4> dos_backup::tfs_scanstart: INF - starting scan for file directive:<System State:\>
6:00:09.624 PM: [3588.7308] <4> dos_backup::tfs_scanstart: INF - starting scan using name:<System State:\>
6:00:09.624 PM: [3588.7308] <4> dos_backup::tfs_scanstart: INF - in 'pre-backup' mode
6:00:10.266 PM: [3588.7308] <16> dos_backup::V_InitializeSystemState: ERR - FS_AddToSnapshotSet() Failed! (System State:\System Files\System Files) $s
6:00:10.266 PM: [3588.7308] <2> tar_base::V_vTarMsgW: ERR - Volume resolution error for (System State:\System Files\System Files)
6:00:10.267 PM: [3588.7308] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 156: snapshot error encountered
6:00:10.267 PM: [3588.7308] <4> backup_create: INF - NetBackup Temp Directory: 'C:\Program Files\Veritas\\NetBackup\Temp'
6:00:10.268 PM: [3588.7308] <4> tar_backup_tfi::UpdateExcludeListWithVHD: INF - UpdateExludeListWithVHD begin
6:00:11.304 PM: [3588.7308] <4> OVStopCmd: INF - EXIT - status = 0
6:00:11.304 PM: [3588.7308] <2> tar_base::V_Close: closing...
6:00:12.340 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): enter - InitFlags:0x00000101
6:00:12.340 PM: [3588.7308] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): ubs specifics: 0x001d0000
6:00:12.343 PM: [3588.5108] <4> tar_base::keepaliveThread: INF - keepalive thread terminating (reason: WAIT_OBJECT_0)
6:00:12.343 PM: [3588.7308] <4> tar_base::stopKeepaliveThread: INF - keepalive thread has exited. (reason: WAIT_OBJECT_0)
6:00:12.343 PM: [3588.7308] <16> dtcp_read: TCP - failure: recv socket (356) (TCP 10053: Software caused connection abort)
6:00:13.343 PM: [3588.7308] <16> dtcp_read: TCP - failure: recv socket (356) (TCP 10053: Software caused connection abort)
6:00:13.343 PM: [3588.7308] <4> OVShutdown: INF - Finished process
6:00:13.345 PM: [3588.7308] <4> WinMain: INF - Exiting C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe
6:00:15.344 PM: [3588.7308] <4> ov_log::OVClose: INF - Closing log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\111313.LOG
 
 

Kushaal
Level 4

Hi,

I have posted bpbkar and bpfis logs .waiting for suggestion from your end

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

Logging level is 0 - as per the TN that I have posted above, a minimum logging level of 2 is needed. 

Please increase logging level to 2 or 3, retry the backup and then compare your logs with the example in the TN.

Kushaal
Level 4

Hi i have verbose to 3 and have posted the BPfis and bpbkar output.

I crosss verified with TN but i could not understand

But client which we are backing up is not a part of cluster.

Bpfis

19:59:32.573 [7108.3460] <2> logparams: bpfis query -id CHVBUVSAPP_1384352957 -copy 1 
19:59:32.574 [7108.3460] <4> keep_alive_and_snap_control: Starting keep alive thread.
19:59:32.587 [7108.7200] <2> send_keep_alive: INF - brm is gone
19:59:32.658 [7108.3460] <2> vnet_pbxConnect: pbxConnectEx Succeeded
19:59:32.658 [7108.3460] <2> logconnections: BPRD CONNECT FROM 192.168.223.140.52549 TO 192.168.70.94.1556 fd = 500
19:59:32.659 [7108.3460] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
19:59:37.297 [7108.3460] <4> bpfis main: INF - BACKUP START 7108
19:59:37.298 [7108.3460] <32> fis_rebuild_from_db: FTL - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.CHVBUVSAPP_1384352957.1.0
19:59:37.298 [7108.3460] <4> bpfis main: Overriding original online_util() status <12> with <1542>.
19:59:37.298 [7108.3460] <4> keep_alive_and_snap_control: Starting keep alive thread.
19:59:37.298 [7108.3460] <4> bpfis Exit: INF - EXIT STATUS 1542: An existing snapshot is no longer valid and cannot be mounted for subsequent operations
19:59:37.298 [7108.3460] <2> bpfis Exit: INF - Close of stdout complete
 
 
Bpbkar
7:59:28.718 PM: [1004.3628] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\111313.LOG
 
7:59:28.718 PM: [1004.3628] <4> ov_log::OVInit: GENERAL Log Level: 0
7:59:28.718 PM: [1004.3628] <4> ov_log::OVInit: TCP Log Level: 0
7:59:28.718 PM: [1004.3628] <4> ov_log::OVInit: INF - the log mutex: 340
BPBKAR  NetBackup Backup/Archive  7.5GA  [Jun  5 2012]
Copyright © 1993 - 2012 Symantec Corporation, All Rights Reserved.
All Rights Reserved.
 
7:59:28.769 PM: [1004.3628] <2> WinMain: DAT - _pgmptr = 'C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe'
7:59:28.769 PM: [1004.3628] <2> WinMain: DAT - lpCmdLine = '-r 1209600 -ru root -dt 0 -to 0 -bpstart_time 1384353258 -clnt CHVBUVSAPP -class Chennai_CHVBUVSAPP -sched FULL -st FULL -bpstart_to 300 -bpend_to 300 -read_to 300 -ckpt_time 2700 -blks_per_buffer 128 -tir -tir_plus -use_otm -fso -b CHVBUVSAPP_1384352957 -kl 28 -WOFB_enabled -WOFB_fim 0 -WOFB_usage 0 -WOFB_error 0 -ct 13 -use_ofb '
7:59:28.769 PM: [1004.3628] <2> date_debug: DAT - timezone: India Standard Time, offset=-19800, dst: NONE
7:59:28.769 PM: [1004.3628] <2> date_debug: DAT - current time: 1384352968, 11/13/2013 7:59:28 PM
7:59:28.769 PM: [1004.3628] <2> date_debug: DAT - 01/01/94 UCT:  757382400, 1/1/1994 5:30:00 AM
7:59:28.769 PM: [1004.3628] <2> date_debug: DAT - 07/01/94 UCT:  773020800, 7/1/1994 5:30:00 AM
7:59:28.769 PM: [1004.3628] <2> WinMain: DAT - standard input handle = 356
7:59:28.774 PM: [1004.3628] <2> WinMain: DAT - standard input handle is NOT resilient socket.
7:59:28.774 PM: [1004.3628] <2> WinMain: DAT - standard output handle = 204
7:59:28.774 PM: [1004.3628] <2> WinMain: DAT - standard output handle is NOT resilient socket.
7:59:28.774 PM: [1004.3628] <2> WinMain: DAT - standard error handle = 324
7:59:28.774 PM: [1004.3628] <2> WinMain: DAT - standard error handle is NOT resilient socket.
7:59:28.777 PM: [1004.3628] <4> tar_backup_tfi::create: INF - change time comparison:<disabled>
7:59:28.778 PM: [1004.3628] <4> tar_backup::V_SetupJobData: INF - dwJobData: ffffffff
7:59:28.778 PM: [1004.3628] <4> tar_backup::V_SetupJobData: INF -     dwJob: ffffffff
7:59:28.796 PM: [1004.3628] <4> ncfLogConfiguration: INF - Module: libncf, Release: 7.5.0.3 , Build: 06/05/2012 20:00:00 CDT (20120605)
7:59:28.804 PM: [1004.3628] <4> ncfLogConfiguration: INF - Windows version: 6.0.6002, Platform: 2 (Service Pack 2), Service pack: 2.0, Suite: 272, Product type: 3
7:59:28.812 PM: [1004.3628] <4> ncfLogConfiguration: INF - Process architecture: 0, Page size: 4096, Process type: 1, Process level: 586, Processor revision: 6
7:59:28.819 PM: [1004.3628] <4> NcfString::logLocale: INF - Current code page: WINDOWS: 1252  (ANSI - Latin I), Max. character width: 1, Substitution character: 0x3F [?], Unicode substitution character: 0x003f [?.]
7:59:28.819 PM: [1004.3628] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0
7:59:28.820 PM: [1004.3628] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0
7:59:28.820 PM: [1004.3628] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0
7:59:28.820 PM: [1004.3628] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0
7:59:28.821 PM: [1004.3628] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0
7:59:28.821 PM: [1004.3628] <4> dos_backup::V_PreProcessing: INF - user name: root
7:59:28.821 PM: [1004.3628] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup
7:59:28.822 PM: [1004.3628] <2> ov_log::V_GlobalLog: WRN - ubsDetermineExchangeVersion(): RegOpenKeyEx() failed for HKLM\SOFTWARE\MICROSOFT\ExchangeServer\v14\Setup - 0x2.
7:59:28.822 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0
7:59:28.928 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C:
7:59:28.928 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: D:
7:59:28.928 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Terminal Services
7:59:28.928 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Windows Network
7:59:28.928 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Symantec SNAC Network Provider
7:59:28.928 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: CHVBUVSAPP\Microsoft SQL Server Instances
7:59:28.928 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - DumpChildDleInfo() Child DLE Device Name: CHVBUVSAPP\MSSQLSERVER
7:59:28.928 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: System?State
7:59:28.928 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Active Directory Application Mode
7:59:28.957 PM: [1004.3628] <2> tar_base::V_vTarMsgW: INF - BACKUP START 1004
7:59:29.171 PM: [1004.3628] <2> tar_backup::V_SetupProcessContinue: TAR - CONTINUE BACKUP received
7:59:29.171 PM: [1004.3628] <2> tar_base::V_vTarMsgW: INF - CONTINUE BACKUP message received
7:59:29.171 PM: [1004.3628] <4> tar_backup_cpr::start: INF - checkpoint thread started
7:59:29.356 PM: [1004.3628] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = ALL_LOCAL_DRIVES
7:59:29.356 PM: [1004.6340] <4> tar_base::keepaliveThread: INF - keepalive thread is active with an interval of 60 seconds
7:59:30.396 PM: [1004.3628] <2> NBJournalDataCollection::NBJournalDataCollection: INF - volume guid:<\\?\Volume{8b76f79f-ac69-11e1-b75c-806e6f6e6963}\>
7:59:30.396 PM: [1004.3628] <2> NBJournalDataCollection::NBJournalDataCollection: INF - mounted at:<C:\>:<\\?\Volume{8b76f79f-ac69-11e1-b75c-806e6f6e6963}\>
7:59:30.396 PM: [1004.3628] <2> NBJournalDataCollection::NBJournalDataCollection: INF - not adding to collection, volume:<\\?\Volume{8b76f79f-ac69-11e1-b75c-806e6f6e6963}\>:<C:\> is configured to not use the change journal
7:59:30.396 PM: [1004.3628] <2> NBJournalDataCollection::NBJournalDataCollection: INF - volume guid:<\\?\Volume{abba26b4-ae04-11e1-8e17-00155ddf6505}\>
7:59:30.396 PM: [1004.3628] <2> NBJournalDataCollection::NBJournalDataCollection: INF - mounted at:<D:\>:<\\?\Volume{abba26b4-ae04-11e1-8e17-00155ddf6505}\>
7:59:30.396 PM: [1004.3628] <2> NBJournalDataCollection::NBJournalDataCollection: INF - not adding to collection, volume:<\\?\Volume{abba26b4-ae04-11e1-8e17-00155ddf6505}\>:<D:\> is configured to not use the change journal
7:59:30.396 PM: [1004.3628] <4> dos_backup::V_Initialize: INF - created change journal collection
7:59:30.396 PM: [1004.3628] <4> V_Snapshot::V_Snapshot_Query: INF - Attempting to query volume snapshots: bpfis query -id CHVBUVSAPP_1384352957  -copy 1
7:59:37.400 PM: [1004.3628] <4> V_Snapshot::V_Snapshot_ParseBpfisOutput: INF - Snapshot creation, FIS_ID: CHVBUVSAPP_1384352957
7:59:37.400 PM: [1004.3628] <2> tar_backup_vxbsa::add: INF - called with '/'
7:59:37.400 PM: [1004.3628] <2> _expand_root: INF - checking for root expansion:<:\>
7:59:37.400 PM: [1004.3628] <2> _expand_root: INF - Added: C:\
7:59:37.400 PM: [1004.3628] <2> _expand_root: INF - Added: D:\
7:59:37.400 PM: [1004.3628] <2> _expand_root: INF - Added: Shadow Copy Components:\
7:59:37.400 PM: [1004.3628] <2> _expand_root: INF - Added: System State:\
7:59:37.400 PM: [1004.3628] <2> _expand_root: INF - checking for root expansion:<C:\>
7:59:37.400 PM: [1004.3628] <2> _expand_root: INF - checking for root expansion:<D:\>
7:59:37.400 PM: [1004.3628] <2> _expand_root: INF - checking for root expansion:<Shadow Copy Components:\>
7:59:37.400 PM: [1004.3628] <2> _expand_root: INF - checking for root expansion:<System State:\>
7:59:37.400 PM: [1004.3628] <2> _fix_registry: INF - checking for registry expansion:<C:\>
7:59:37.400 PM: [1004.3628] <2> _fix_registry: INF - checking for registry expansion:<D:\>
7:59:37.400 PM: [1004.3628] <2> _fix_registry: INF - checking for registry expansion:<Shadow Copy Components:\>
7:59:37.400 PM: [1004.3628] <2> _fix_registry: INF - checking for registry expansion:<System State:\>
7:59:37.400 PM: [1004.3628] <2> _validate_change_journal_use: ERR - change journal not supported for <Shadow Copy Components:\>,  prevent change journal usage
7:59:37.400 PM: [1004.3628] <2> _validate_change_journal_use: ERR - change journal not supported for <System State:\>,  prevent change journal usage
7:59:37.431 PM: [1004.3628] <4> dos_backup::V_VerifyFileSystem: INF - corrected name:<C:\>
7:59:37.431 PM: [1004.3628] <4> dos_backup::V_VerifyFileSystem: INF - corrected name:<D:\>
7:59:37.431 PM: [1004.3628] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'C:\' --> 10020002
7:59:37.431 PM: [1004.3628] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'D:\' --> 10020002
7:59:39.336 PM: [1004.3628] <4> dos_backup::V_VerifyFileList: INF - Hidden Device, Ignoring filelist entry for 'Shadow Copy Components:\'
7:59:39.336 PM: [1004.3628] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'Shadow Copy Components:\' --> 10020027
7:59:41.258 PM: [1004.3628] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'System State:\' --> 1002002d
7:59:41.258 PM: [1004.3628] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for '_BACKUP_SPECIAL_OBJECTS AFTER System State:' --> 1002002d
7:59:43.244 PM: [1004.3628] <4> VssSnapshot::V_VssSetMetadata(): INF - Unable to locate DFSR metadata
7:59:44.745 PM: [1004.3628] <4> dos_backup::tfs_scanstart: INF - starting scan for file directive:<System State:\>
7:59:44.745 PM: [1004.3628] <4> dos_backup::tfs_scanstart: INF - starting scan using name:<System State:\>
7:59:44.745 PM: [1004.3628] <4> dos_backup::tfs_scanstart: INF - in 'pre-backup' mode
7:59:45.417 PM: [1004.3628] <16> dos_backup::V_InitializeSystemState: ERR - FS_AddToSnapshotSet() Failed! (System State:\System Files\System Files) $s
7:59:45.417 PM: [1004.3628] <2> tar_base::V_vTarMsgW: ERR - Volume resolution error for (System State:\System Files\System Files)
7:59:45.418 PM: [1004.3628] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 156: snapshot error encountered
7:59:45.418 PM: [1004.3628] <4> backup_create: INF - NetBackup Temp Directory: 'C:\Program Files\Veritas\\NetBackup\Temp'
7:59:45.420 PM: [1004.3628] <4> tar_backup_tfi::UpdateExcludeListWithVHD: INF - UpdateExludeListWithVHD begin
7:59:46.471 PM: [1004.3628] <4> OVStopCmd: INF - EXIT - status = 0
7:59:46.471 PM: [1004.3628] <2> tar_base::V_Close: closing...
7:59:47.528 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): enter - InitFlags:0x00000101
7:59:47.528 PM: [1004.3628] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): ubs specifics: 0x001d0000
7:59:47.532 PM: [1004.6340] <4> tar_base::keepaliveThread: INF - keepalive thread terminating (reason: WAIT_OBJECT_0)
7:59:47.532 PM: [1004.3628] <4> tar_base::stopKeepaliveThread: INF - keepalive thread has exited. (reason: WAIT_OBJECT_0)
7:59:47.532 PM: [1004.3628] <16> dtcp_read: TCP - failure: recv socket (356) (TCP 10053: Software caused connection abort)
7:59:48.532 PM: [1004.3628] <16> dtcp_read: TCP - failure: recv socket (356) (TCP 10053: Software caused connection abort)
7:59:48.532 PM: [1004.3628] <4> OVShutdown: INF - Finished process
7:59:48.568 PM: [1004.3628] <4> WinMain: INF - Exiting C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe
7:59:50.567 PM: [1004.3628] <4> ov_log::OVClose: INF - Closing log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\111313.LOG