4:27:56.072 AM: [6084.5232] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\101316.LOG 4:27:56.072 AM: [6084.5232] <4> ov_log::OVInit: GENERAL Log Level: 0 4:27:56.072 AM: [6084.5232] <4> ov_log::OVInit: TCP Log Level: 0 4:27:56.072 AM: [6084.5232] <4> ov_log::OVInit: INF - the log mutex: 572 BPBKAR NetBackup Backup/Archive 7.1GA [Aug 25 2011] Copyright © 1993 - 2011 Symantec Corporation, All Rights Reserved. All Rights Reserved. 4:27:56.072 AM: [6084.5232] <2> WinMain: DAT - _pgmptr = 'C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe' 4:27:56.072 AM: [6084.5232] <2> WinMain: DAT - lpCmdLine = '-r 3628800 -ru root -dt 8815208 -to 0 -bpstart_time 0 -clnt sbdntdbp012 -class SBD_C_NT_7YR_ALD -sched DINC -st INCR -bpstart_to 900 -bpend_to 900 -read_to 14400 -ckpt_time 900 -blks_per_buffer 127 -use_otm -use_ofb -b sbdntdbp012_1476274031 -kl 5 -fso -WOFB_enabled -WOFB_fim 1 -WOFB_usage 0 -WOFB_error 0 -ct 13 ' 4:27:56.072 AM: [6084.5232] <2> date_debug: DAT - timezone: AUS Eastern Standard Time, offset=-36000, dst: AUS Eastern Daylight Time 4:27:56.087 AM: [6084.5232] <2> date_debug: DAT - current time: 1476293276, 13/10/2016 4:27:56 AM 4:27:56.087 AM: [6084.5232] <2> date_debug: DAT - 01/01/94 UCT: 757382400, 1/01/1994 11:00:00 AM 4:27:56.087 AM: [6084.5232] <2> date_debug: DAT - 07/01/94 UCT: 773020800, 1/07/1994 11:00:00 AM 4:27:56.087 AM: [6084.5232] <2> WinMain: DAT - standard input handle = 464 4:27:56.087 AM: [6084.5232] <2> WinMain: DAT - standard output handle = 688 4:27:56.087 AM: [6084.5232] <2> WinMain: DAT - standard error handle = 700 4:27:56.119 AM: [6084.5232] <8> tar_process_backup_args: WRN - invalid option: -bpstart_time 0 4:27:56.119 AM: [6084.5232] <4> tar_backup::V_SetupJobData: INF - dwJobData: ffffffff 4:27:56.119 AM: [6084.5232] <4> tar_backup::V_SetupJobData: INF - dwJob: ffffffff 4:27:56.150 AM: [6084.5232] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0 4:27:56.150 AM: [6084.5232] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0 4:27:56.150 AM: [6084.5232] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0 4:27:56.150 AM: [6084.5232] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0 4:27:56.150 AM: [6084.5232] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0 4:27:56.150 AM: [6084.5232] <4> dos_backup::V_PreProcessing: INF - user name: root 4:27:56.150 AM: [6084.5232] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup 4:27:56.150 AM: [6084.5232] <2> ov_log::V_GlobalLog: WRN - ubsDetermineExchangeVersion(): RegOpenKeyEx() failed for HKLM\SOFTWARE\MICROSOFT\ExchangeServer\v14\Setup - 0x2. 4:27:56.150 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C: 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: D: 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Q: 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Z: 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Terminal Services 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Windows Network 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Web Client Network 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: SBDNTDBP012 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: SBDNTDBP012\DRINS4 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: SBDNTDBP012\DRINS5 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: SBDNTDBP012\DRINS6 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: SBDNTDBP012\DRINS7 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: SBDNTDBP012\DRINS8 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Shadow?Copy?Components 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: System?State 4:27:56.462 AM: [6084.5232] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Active Directory Application Mode 4:27:56.478 AM: [6084.5232] <2> tar_base::V_vTarMsgW: INF - BACKUP START 6084 4:27:56.478 AM: [6084.5232] <2> tar_backupt_tfi::create: TAR - Incremental backup using the archive bit 4:27:56.478 AM: [6084.5232] <2> tar_backup::V_SetupProcessContinue: TAR - CONTINUE BACKUP received 4:27:56.478 AM: [6084.5232] <2> tar_base::V_vTarMsgW: INF - CONTINUE BACKUP message received 4:27:56.478 AM: [6084.5232] <4> tar_backup_cpr::start: INF - checkpoint thread started 4:27:56.478 AM: [6084.5232] <2> tar_backup_cpr::parse: INF - checkpoint restart message - 20434808 3624 0 0 3850 0 0 0 6 798945280 9 3 127 0 1 53 /Q/SQL_DR_2016/pWinBeatADLNTDVP003SQLEXPRESS_1of1.bak 4:27:56.478 AM: [6084.5232] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = ALL_LOCAL_DRIVES 4:27:56.478 AM: [6084.700] <4> tar_base::keepaliveThread: INF - keepalive thread is active with an interval of 60 seconds 4:27:56.587 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_Query: INF - Attempting to query volume snapshots: bpfis query -id sbdntdbp012_1476274031 4:27:57.587 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_ParseBpfisOutput: INF - Snapshot creation, FIS_ID: sbdntdbp012_1476274031 4:27:57.587 AM: [6084.5232] <2> tar_backup_vxbsa::add: INF - called with '/' 4:27:57.587 AM: [6084.5232] <4> dos_backup::V_VerifyFileSystem: INF - Added: C:\ 4:27:57.587 AM: [6084.5232] <4> dos_backup::V_VerifyFileSystem: INF - Added: D:\ 4:27:57.587 AM: [6084.5232] <4> dos_backup::V_VerifyFileSystem: INF - Added: Q:\ 4:27:57.587 AM: [6084.5232] <4> dos_backup::V_VerifyFileSystem: INF - Added: Z:\ 4:27:57.587 AM: [6084.5232] <4> dos_backup::V_VerifyFileSystem: INF - Added: Shadow Copy Components:\ 4:27:57.587 AM: [6084.5232] <4> dos_backup::V_VerifyFileSystem: INF - Added: System State:\ 4:27:57.587 AM: [6084.5232] <2> tar_base::V_vTarMsgW: WRN - You have chosen to ignore unresolved volumes for Shadow Copy Components backups. Your backup will exit status zero even if the following volumes cannot be resolved Q: 4:27:57.587 AM: [6084.5232] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'C:\' --> 10020002 4:27:57.587 AM: [6084.5232] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'D:\' --> 10020002 4:27:57.587 AM: [6084.5232] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'Q:\' --> 10020002 4:27:57.587 AM: [6084.5232] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'Z:\' --> 10020002 4:27:59.322 AM: [6084.5232] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'Shadow Copy Components:\' --> 10020027 4:28:00.869 AM: [6084.5232] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'System State:\' --> 1002002d 4:28:00.869 AM: [6084.5232] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for '_BACKUP_SPECIAL_OBJECTS AFTER System State:' --> 1002002d 4:28:02.368 AM: [6084.5232] <4> VssSnapshot::V_VssSetMetadata(): INF - Unable to locate DFSR metadata 4:28:02.884 AM: [6084.5232] <4> dos_backup::V_InitializeShadowCopy: INF - ============================================ 4:28:02.884 AM: [6084.5232] <4> dos_backup::V_InitializeShadowCopy: INF - ShadowCopy PrePost: Begin 4:28:06.025 AM: [6084.5232] <4> dos_backup::tfs_findfirst: INF - unable to find first file: 'Shadow Copy Components:\System Service\Background Intelligent Transfer Service\' 4:28:06.040 AM: [6084.5232] <4> VssSnapshot::V_VssVolumeSnapshot(): INF - Drive 'C:' added to VSS Volume Set 4:28:12.415 AM: [6084.5232] <4> VssSnapshot::V_VssVolumeSnapshot(): INF - VSS Volume Set snapped 4:28:12.415 AM: [6084.5232] <4> VssSnapshot::V_VssVolumeSnapshot(): INF - About to commence post-snap unbounded association checks 4:28:12.415 AM: [6084.5232] <4> dos_backup::V_InitializeShadowCopy: INF - ShadowCopy PrePost: End 4:28:12.415 AM: [6084.5232] <4> dos_backup::V_InitializeShadowCopy: INF - ============================================ 4:28:12.415 AM: [6084.5232] <4> VssSnapshot::V_VssSetMetadata(): INF - Unable to locate DFSR metadata 4:28:17.868 AM: [6084.5232] <4> dos_backup::tfs_scanstart: INF - Backup Special Objects request AFTER System State: 4:28:20.837 AM: [6084.5232] <4> dos_backup::tfs_findfirst: INF - unable to find first file: 'System State:\' 4:28:20.853 AM: [6084.5232] <4> VssSnapshot::V_VssVolumeSnapshot(): INF - Drive 'C:' added to VSS Volume Set 4:28:20.868 AM: [6084.5232] <4> VssSnapshot::V_VssVolumeSnapshot(): INF - Drive 'c:' added to VSS Volume Set 4:28:27.353 AM: [6084.5232] <4> VssSnapshot::V_VssVolumeSnapshot(): INF - VSS Volume Set snapped 4:28:27.353 AM: [6084.5232] <4> VssSnapshot::V_VssVolumeSnapshot(): INF - About to commence post-snap unbounded association checks 4:28:27.353 AM: [6084.5232] <4> backup_create: INF - NetBackup Temp Directory: 'C:\Program Files\Veritas\\NetBackup\Temp' 4:28:27.353 AM: [6084.5232] <16> tar_backup::SetExcludeFileList: **** DBG **** - alternate client fileter file is null 4:28:27.353 AM: [6084.5232] <4> tar_backup_tfi::UpdateExcludeListWithVHD: INF - UpdateExludeListWithVHD begin 4:28:27.384 AM: [6084.5232] <2> ov_log::V_GlobalLogEx: Failed to load VDS . (0x80070422)4:28:27.384 AM: [6084.5232] <4> tar_backup_tfi::UpdateExcludeListWithVHD: INF - Unable to initialize virtual disk service. .vhd files may be inclued for backup 4:28:27.384 AM: [6084.5232] <2> tar_base::V_vTarMsgW: INF - Enabling volume snapshots for (Q:), please wait... 4:28:27.384 AM: [6084.5232] <4> V_DetermineMountInfo: INF - Checking Volume \\?\Volume{f4d5d254-aff5-11df-aa69-001a64c2d4b6}\ for '' 4:28:27.384 AM: [6084.5232] <4> V_DetermineMountInfo: INF - Adding NTFS Volume Q:\ ==> \\?\Volume{f4d5d254-aff5-11df-aa69-001a64c2d4b6}\ 4:28:27.384 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - ====================================================================== 4:28:27.384 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Attempting to create snapshots for 'Q:' 4:28:27.384 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - CREATE request: C:\Program Files\Veritas\NetBackup\bin\bpfis create -owner NBU -fso -WOFB -fim VSS:prov_type=1 -id sbdntdbp012_1476274031 Q:\ 4:28:54.384 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_AddMappings: INF - V_Snapshot_AddMappings input parameters: source path = "Q:\" snap path = "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy307\" mount path = "(null)" 4:28:54.384 AM: [6084.5232] <4> V_Snapshot::V_GetSourceVolume: INF - source = "Q:\" snapshot = "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy307\" 4:28:54.384 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_AddMappings: INF - Volume Snapshot Mapping: \\?\Volume{f4d5d254-aff5-11df-aa69-001a64c2d4b6}\ --> GLOBALROOT\Device\HarddiskVolumeShadowCopy307 4:28:54.384 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_ParseBpfisOutput: INF - Snapshot creation, FIS_ID: sbdntdbp012_1476274031 4:28:54.384 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Snapshot creation was successful 4:28:54.384 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Snapshot provider: VSS 4:28:54.384 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - ====================================================================== 4:28:54.384 AM: [6084.5232] <2> tar_base::V_vTarMsgW: INF - Volume snapshots enabled 4:28:54.493 AM: [6084.5232] <2> tar_base::V_vTarMsgW: INF - Excluded: Q:\RECYCLER 4:28:54.493 AM: [6084.5232] <4> dos_backup::tfs_startdir: INF - Stopping scan requested for mount point: Q:\SAN_DEV_Sqldevices1_Q 4:28:54.493 AM: [6084.5232] <4> dos_backup::tfs_startdir: INF - Stopping scan requested for mount point: Q:\SAN_DEV_Sqldevices2_Q 4:28:54.603 AM: [6084.5232] <2> ov_log::V_GlobalLogEx: INF - file_access (constructor): 0 non-NTFS volumes 4:28:54.634 AM: [6084.5232] <4> dos_backup::tfs_include: INF - folder (SQL_DR_2016) has been created recently (since 3/07/2016 2:47:48 AM). It will be backed up in full. 4:28:54.634 AM: [6084.5232] <4> dos_backup::tfs_include: INF - folder (SQL_DR_2016) has been created recently (since 3/07/2016 2:47:48 AM). It will be backed up in full. 4:28:54.649 AM: [6084.5232] <2> tar_base::V_vTarMsgW: INF - Enabling volume snapshots for (Z:), please wait... 4:28:54.649 AM: [6084.5232] <4> V_DetermineMountInfo: INF - Checking Volume \\?\Volume{92ed228c-288b-11dd-be8e-001a64c2d4b6}\ for '' 4:28:54.649 AM: [6084.5232] <4> V_DetermineMountInfo: INF - Adding NTFS Volume Z:\ ==> \\?\Volume{92ed228c-288b-11dd-be8e-001a64c2d4b6}\ 4:28:54.649 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_Destroy: INF - Attempting to destroy volume snapshots: bpfis delete -id sbdntdbp012_1476274031 4:28:57.649 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_Destroy: INF - Snapshot Destroy EXIT STATUS 0: the requested operation was successfully completed 4:28:57.649 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - ====================================================================== 4:28:57.649 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Attempting to create snapshots for 'Z:' 4:28:57.649 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - CREATE request: C:\Program Files\Veritas\NetBackup\bin\bpfis create -owner NBU -fso -WOFB -fim VSS:prov_type=1 -id sbdntdbp012_1476274031 Z:\ 4:29:22.649 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_AddMappings: INF - V_Snapshot_AddMappings input parameters: source path = "Z:\" snap path = "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy308\" mount path = "(null)" 4:29:22.649 AM: [6084.5232] <4> V_Snapshot::V_GetSourceVolume: INF - source = "Z:\" snapshot = "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy308\" 4:29:22.649 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_AddMappings: INF - Volume Snapshot Mapping: \\?\Volume{92ed228c-288b-11dd-be8e-001a64c2d4b6}\ --> GLOBALROOT\Device\HarddiskVolumeShadowCopy308 4:29:22.649 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_ParseBpfisOutput: INF - Snapshot creation, FIS_ID: sbdntdbp012_1476274031 4:29:22.649 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Snapshot creation was successful 4:29:22.649 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Snapshot provider: VSS 4:29:22.649 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - ====================================================================== 4:29:22.649 AM: [6084.5232] <2> tar_base::V_vTarMsgW: INF - Volume snapshots enabled 4:29:22.649 AM: [6084.5232] <2> tar_base::V_vTarMsgW: INF - Excluded: Z:\RECYCLER 4:29:24.743 AM: [6084.5232] <2> tar_backup_cpr::position: INF - checkpoint restart position - /Shadow Copy Components/ 4:29:25.821 AM: [6084.5232] <4> dos_backup::tfs_include: INF - folder (System Service) has been created recently (since 3/07/2016 2:47:48 AM). It will be backed up in full. 4:29:33.837 AM: [6084.5232] <4> dos_backup::tfs_findfirst: INF - unable to find first file: 'Shadow Copy Components:\System Service\Background Intelligent Transfer Service\' 4:29:37.024 AM: [6084.5232] <4> dos_backup::tfs_include: INF - folder (System Files) has been created recently (since 3/07/2016 2:47:48 AM). It will be backed up in full. 4:32:02.820 AM: [6084.5232] <4> dos_backup::tfs_include: INF - folder (Registry) has been created recently (since 3/07/2016 2:47:48 AM). It will be backed up in full. 4:32:06.476 AM: [6084.5232] <4> dos_backup::tfs_include: INF - folder (COM+ Class Registration Database) has been created recently (since 3/07/2016 2:47:48 AM). It will be backed up in full. 4:32:06.554 AM: [6084.5232] <4> dos_backup::tfs_scanstart: INF - Backup Special Objects request AFTER System State: 4:32:07.554 AM: [6084.5232] <2> tar_base::V_vTarMsgW: INF - Enabling volume snapshots for (System State:), please wait... 4:32:07.554 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_Create: INF - Adding Volume System State:\ 4:32:07.554 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_Create: INF - Unable to snapshot volume (Invalid source volume): System State:\ 4:32:07.554 AM: [6084.5232] <2> tar_base::V_vTarMsgW: INF - Volume snapshots not enabled 4:32:09.539 AM: [6084.5232] <4> dos_backup::tfs_findfirst: INF - unable to find first file: 'System State:\' 4:32:09.539 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_Destroy: INF - Attempting to destroy volume snapshots: bpfis delete -id sbdntdbp012_1476274031 4:32:12.539 AM: [6084.5232] <4> V_Snapshot::V_Snapshot_Destroy: INF - Snapshot Destroy EXIT STATUS 0: the requested operation was successfully completed 4:32:12.539 AM: [6084.5232] <2> tar_base::backup_finish: TAR - backup: 3863 files 4:32:12.539 AM: [6084.5232] <2> tar_base::backup_finish: TAR - backup: file data: 272339216 bytes 1 gigabytes 4:32:12.539 AM: [6084.5232] <2> tar_base::backup_finish: TAR - backup: image data: 1071313920 bytes 10 gigabytes 4:32:12.539 AM: [6084.5232] <2> tar_base::backup_finish: TAR - backup: elapsed time: 225 secs 52483254 bps 4:32:12.539 AM: [6084.5232] <4> tar_backup::backup_done_state: INF - number of file directives not found: 0 4:32:12.539 AM: [6084.5232] <4> tar_backup::backup_done_state: INF - number of file directives found: 10 4:32:12.539 AM: [6084.700] <4> tar_base::keepaliveThread: INF - keepalive thread terminating (reason: WAIT_OBJECT_0) 4:32:12.539 AM: [6084.5232] <4> tar_base::stopKeepaliveThread: INF - keepalive thread has exited. (reason: WAIT_OBJECT_0)