Error during backup of shadow copy components
Hi everyone,
I have a strange problem and I hope that anyone can help me.
I use NBU 7.5.0.3 for my backups.
The problem regards the bck of a phisical server with nbu policy type "MS-windos" with backup of "all_local_drives" and so also shadow copy components.
The client is a win srv 2008 R2 Standard and I backup it every week only the saturday.
Not all W.E. but sometimes, backup of Shadow copy components fail wih retur code 69. From job details I can find only general info about the error:
[...]
28/07/2012 05:38:25 - end Snapshot, Stop On Error; elapsed time: 00:00:00
28/07/2012 05:38:25 - begin Snapshot, Delete Snapshot
28/07/2012 05:38:27 - started process bpbrm (4472)
28/07/2012 05:38:29 - Info bpbrm(pid=4472) Starting delete snapshot processing
28/07/2012 05:38:29 - Info bpfis(pid=0) Snapshot will not be deleted
Status 69
28/07/2012 05:38:32 - Info bpfis(pid=5256) Backup started
28/07/2012 05:38:35 - end writing
Status 0
28/07/2012 05:38:35 - end Snapshot, Delete Snapshot; elapsed time: 00:00:10
28/07/2012 05:38:35 - begin Snapshot, End Notify Script
28/07/2012 05:38:35 - Info RUNCMD(pid=2344) started
28/07/2012 05:38:35 - Info RUNCMD(pid=2344) exiting with status: 0
Status 0
28/07/2012 05:38:35 - end Snapshot, End Notify Script; elapsed time: 00:00:00
Status 69
28/07/2012 05:38:35 - end operation
invalid filelist specification(69)
and the other log releated to the shadow copy component is:
28/07/2012 04:00:54 - Info nbjm(pid=5740) starting backup job (jobid=146707) for client altair, policy altair-all_PD, schedule Full_sporadico
28/07/2012 04:00:54 - estimated 0 Kbytes needed
28/07/2012 04:00:54 - Info nbjm(pid=5740) started backup (backupid=altair_1343440854) job for client altair, policy altair-all_PD, schedule Full_sporadico on storage unit arcadia-DP-deduplica
28/07/2012 04:00:56 - started process bpbrm (2972)
28/07/2012 04:01:06 - Info bpbrm(pid=2972) altair is the host to backup data from
28/07/2012 04:01:06 - Info bpbrm(pid=2972) reading file list from client
28/07/2012 04:01:07 - connecting
28/07/2012 04:01:09 - connected; connect time: 00:00:02
28/07/2012 04:01:10 - Info bpbrm(pid=2972) starting bpbkar32 on client
28/07/2012 04:01:14 - Info bpbkar32(pid=3344) Backup started
28/07/2012 04:01:14 - Info bptm(pid=2112) start
28/07/2012 04:01:15 - Info bptm(pid=2112) using 262144 data buffer size
28/07/2012 04:01:15 - Info bptm(pid=2112) setting receive network buffer to 262144 bytes
28/07/2012 04:01:15 - Info bptm(pid=2112) using 128 data buffers
28/07/2012 04:01:15 - Info arcadia(pid=2112) Using OpenStorage client direct to backup from client altair to arcadia
28/07/2012 04:01:19 - begin writing
28/07/2012 04:34:54 - Error bpbrm(pid=2972) from client altair: ERR - Unable to backup System State or Shadow Copy. Please check the state of VSS and associated Writers.ERR - Unable to backup System State or Shadow Copy. Please check the state of VSS and associated Writers.INF - Estimate:-1 -1
28/07/2012 04:34:54 - Warning bpbrm(pid=2972) from client altair: WRN - can't open object: Shadow Copy Components: (BEDS 0xE000FECB: A failure occurred accessing the backup component document.)
28/07/2012 04:34:54 - Error bpbrm(pid=2972) from client altair: ERR - Unable to backup System State or Shadow Copy. Please check the state of VSS and associated Writers.JBD - bpbkar waited 0 times for empty buffer, delayed 0 times.
28/07/2012 04:39:13 - Info arcadia(pid=2112) StorageServer=PureDisk:arcadia; Report=PDDO Stats for (arcadia): scanned: 1 KB, CR sent: 0 KB, CR sent over FC: 0 KB, dedup: 100.0%, cache hits: 0 (0.0%)
28/07/2012 04:39:19 - Error bpbrm(pid=2972) could not send server status message
28/07/2012 04:39:21 - end writing; write time: 00:38:02
invalid filelist specification(69)
I have increased logging from the client and from bpbkar I can see:
[...]
04:34:53.442: [3344.3620] <2> ov_log::V_GlobalLog: INF - Status VSS_E_BAD_STATE (0x80042301) getting writer metadata count in SHADOW::GenerateLogicalBackupDirectoryTree
04:34:53.442: [3344.3620] <2> ov_log::V_GlobalLog: INF -
04:34:53.442: [3344.3620] <2> ov_log::V_GlobalLog: INF - ****** Tree - "SHADOW::LogicalDirectoryTree" ******
04:34:53.442: [3344.3620] <2> ov_log::V_GlobalLog: INF - -----------------------------------------------------------------------------------
04:34:53.442: [3344.3620] <2> ov_log::V_GlobalLog: INF -
04:34:53.458: [3344.3620] <2> ov_log::V_GlobalLog: INF - Status FS_WRITER_METADATA_FAILURE (0xE000FEC9) generating logical directory tree when attaching to Shadow?Copy?Components Dle
04:34:53.458: [3344.3620] <2> ov_log::V_GlobalLog: INF - AD:Status FS_WRITER_METADATA_FAILURE (0xE000FEC9) attaching 'Shadow?Copy?Components' in SystemState::InitializeShadowCopy:368
04:34:53.458: [3344.3620] <2> ov_log::V_GlobalLog: INF - AD:Status FS_WRITER_METADATA_FAILURE (0xE000FEC9) initializing Shadow Copy in SystemState::AttachToDLE:710
04:34:53.473: [3344.3620] <2> ov_log::V_GlobalLog: ERR - BEDS_AttachToDLE():FS_AttachToDLE() DeviceName:'System?State' BackupReason:0x400 Failed! (0xE000FEC9:A failure occurred accessing the Writer metadata.
)
04:34:53.473: [3344.3620] <2> ov_log::V_GlobalLog: INF - v_beds::V_FindFirst() EXIT Name: bRC:false LastError:0xFFFFFEC9:0xa000fec9 (2684419785)
04:34:53.473: [3344.3620] <4> tar_base::V_vTarMsgW: INF - tar message received from dos_backup::tfs_startdir
04:34:53.473: [3344.3620] <2> tar_base::V_vTarMsgW: ERR - Unable to backup System State or Shadow Copy. Please check the state of VSS and associated Writers.04:34:53.473: [3344.3620] <4> dos_backup::tfs_scanstart: INF - Backup Special Objects request AFTER System State:
04:34:53.473: [3344.3620] <4> dos_backup::tfs_scanstart: INF - starting scan for file directive:<_BACKUP_SPECIAL_OBJECTS AFTER System State:>
04:34:53.473: [3344.3620] <4> dos_backup::tfs_scanstart: INF - starting scan using name:<System State:\>
04:34:53.473: [3344.3620] <4> dos_backup::tfs_scanstart: INF - in 'pre-backup' mode
04:34:53.473: [3344.3620] <4> dos_backup::tfs_startdir: INF - volume guid:<>
04:34:53.473: [3344.3620] <4> dos_backup::tfs_startdir: INF - volume mount point:<>
04:34:53.473: [3344.3620] <2> ov_log::V_GlobalLog: INF - v_beds::V_FindFirst() ENTER Name:System State: Mode:4
04:34:53.473: [3344.3620] <2> ov_log::V_GlobalLog: DBG - v_beds::V_FindFirst() Device:System State: Obj: Pattern:(null)
[...]
I found a lot of thech notes:
here is the first one i have found: http://support.microsoft.com/kb/975688
Really need to look in the System and Application event logs after a failure to see what it is reporting
In general you will need a reboot to get them stable again anyway