Recycle Backup Failures

[57fda83b-6c77-4fb3-a638-b5a04b5b69a3]

Having lots of issues with EMC (sorry, Roxio) Retrospect lately.

 

We like to keep a range of 1 to 2 weeks worth of backups for each of our servers. On the weekends, we perform Recycle backups on one of two sets of rotating backup sets to help preserve disk space on our NAS. To illustrate, Set A is recycled on Sunday (day 1), and backed up normally Monday through Saturday (days 2 to 7). Set B is recycled on the following Sunday (day 8), then backed up Normally the following Monday through Saturday (days 9 to 14). This cycle then repeats starting over with Set A on the very next Sunday (day 15). This strategy allows us access to Snapshots from between a minimum of one day, and a maximum of one to two weeks, depending on the day a Restore is initiated. Our NAS is a QNAP.

 

We perform Normal backups on all of our servers on a nightly basis without incident. However, lately the Recycle backups that occur on Sunday are intermittently failing. Just this past Sunday, only one succeeded. I will post the logs below. The first is an example of one of the jobs that failed:

 

 

+ Recycle backup using TBAS1 Blue Recycle at 3/20/2011 4:00 AM (Execution unit 1)

To Backup Set TBAS1 Blue...

3/20/2011 4:00:15 AM: Recycle backup: The Backup Set was reset

 

- 3/20/2011 4:00:15 AM: Copying Backed Up Data Folders on tbas1

The Backup Set member "1-TBAS1 Blue" is corrupt or has data from another set.

3/21/2011 7:46:38 AM: Execution stopped by operator

Remaining: 93361 files, 97.6 GB

Completed: 0 files, zero KB

Performance: 0.0 MB/minute

Duration: 1 03:46:23 (1 03:45:28 idle/loading/preparing)

 

 

It seems strange, as the first entry at 4:00:15 AM indicates that the backup set was successfully reset (i.e., deleted), but immediately after, when it attempts to begin copying the files, you get the message about the member being corrupt or having data from another set. You can see one day and four hours later the execution was stopped by the operator (me). The activity monitor was open, with a browsing window intended for a user to choose a location for a new member for the backup set.

 

Five other backups resulted in the same problem. However, one was somehow able to succeed, having its script set up in essentially an identical way. Here is its log:

 

+ Recycle backup using TBAS2 Sys State Recycle at 3/20/2011 4:00 PM (Execution unit 3)

To Backup Set TBAS2 System State...

3/20/2011 4:00:00 PM: Recycle backup: The Backup Set was reset

 

- 3/20/2011 4:00:00 PM: Copying Local Disk (C:) on tbas2

File "C:\WINDOWS\SYSMSI\SSEE\MSSQL.2005\MSSQL\Data\master.mdf": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\SYSMSI\SSEE\MSSQL.2005\MSSQL\Data\mastlog.ldf": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\SYSMSI\SSEE\MSSQL.2005\MSSQL\Data\model.mdf": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\SYSMSI\SSEE\MSSQL.2005\MSSQL\Data\modellog.ldf": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\SYSMSI\SSEE\MSSQL.2005\MSSQL\Data\msdbdata.mdf": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\SYSMSI\SSEE\MSSQL.2005\MSSQL\Data\msdblog.ldf": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\SYSMSI\SSEE\MSSQL.2005\MSSQL\Data\tempdb.mdf": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\SYSMSI\SSEE\MSSQL.2005\MSSQL\Data\templog.ldf": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\system32\dhcp\dhcp.mdb": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\system32\dhcp\j50.log": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\system32\dhcp\j5010F25.log": can't read, error -1101 ( file/directory not found)

File "C:\WINDOWS\system32\dhcp\j50tmp.log": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\system32\dhcp\tmp.edb": can't read, error -1020 ( sharing violation)

File "C:\WINDOWS\system32\dhcp\backup\new\j5010F24.log": can't read, error -1101 ( file/directory not found)

File "C:\WINDOWS\system32\dhcp\backup\new\j5010F25.log": can't read, error -1101 ( file/directory not found)

File "C:\Documents and Settings\All Users\Application Data\Kaspersky Lab\Kaspersky Administration Kit\8.0\temp\retranslation\rollback\bases\av\": can't read security information, error -1101 ( file/directory not found)

File "C:\Documents and Settings\All Users\Application Data\Kaspersky Lab\Kaspersky Administration Kit\8.0\temp\retranslation\rollback\bases\av\emu\": can't read security information, error -1101 ( file/directory not found)

File "C:\Documents and Settings\All Users\Application Data\Kaspersky Lab\Kaspersky Administration Kit\8.0\temp\retranslation\rollback\bases\av\kdb\": can't read security information, error -1101 ( file/directory not found)

File "C:\Documents and Settings\All Users\Application Data\Kaspersky Lab\Kaspersky Administration Kit\8.0\temp\retranslation\rollback\bases\av\wa\": can't read security information, error -1101 ( file/directory not found)

File "C:\Documents and Settings\All Users\Application Data\Kaspersky Lab\Kaspersky Administration Kit\8.0\temp\retranslation\rollback\bases\wmuf\": can't read security information, error -1101 ( file/directory not found)

3/20/2011 4:28:16 PM: Snapshot stored, 163.6 MB

3/20/2011 4:28:22 PM: Comparing Local Disk (C:) on tbas2

File "C:\WINDOWS\TTY_00000000.log": different modify date/time (set: 3/20/2011 3:44:00 PM, vol: 3/20/2011 4:13:57 PM)

File "C:\WINDOWS\Debug\UserMode\ChkAcc.bak": different modify date/time (set: 3/20/2011 4:00:00 PM, vol: 3/20/2011 4:02:46 PM)

File "C:\WINDOWS\Debug\UserMode\ChkAcc.log": different modify date/time (set: 3/20/2011 4:02:46 PM, vol: 3/20/2011 4:25:01 PM)

File "C:\WINDOWS\repair\default": different creation date/time (set: 3/14/2011 10:34:53 AM, vol: 3/20/2011 4:25:06 PM)

File "C:\WINDOWS\repair\SAM": different creation date/time (set: 3/14/2011 10:34:53 AM, vol: 3/20/2011 4:25:06 PM)

File "C:\WINDOWS\repair\SECURITY": different creation date/time (set: 3/14/2011 10:34:53 AM, vol: 3/20/2011 4:25:06 PM)

File "C:\WINDOWS\repair\software": different creation date/time (set: 3/14/2011 10:34:53 AM, vol: 3/20/2011 4:25:06 PM)

File "C:\WINDOWS\repair\system": different creation date/time (set: 3/14/2011 10:35:00 AM, vol: 3/20/2011 4:25:11 PM)

File "C:\WINDOWS\repair\Backup\BootableSystemState\ComRegistrationDatabase\ComRegDb.bak": different creation date/time (set: 3/14/2011 10:34:53 AM, vol: 3/20/2011 4:25:06 PM)

File "C:\WINDOWS\repair\Backup\ServiceState\EventLogs\AppEvent.Evt": different creation date/time (set: 3/14/2011 10:34:53 AM, vol: 3/20/2011 4:25:06 PM)

File "C:\WINDOWS\repair\Backup\ServiceState\EventLogs\dfsr.evt": different creation date/time (set: 3/14/2011 10:34:55 AM, vol: 3/20/2011 4:25:08 PM)

File "C:\WINDOWS\repair\Backup\ServiceState\EventLogs\EventCollector-Operational.Evt": different creation date/time (set: 3/14/2011 10:34:56 AM, vol: 3/20/2011 4:25:09 PM)

File "C:\WINDOWS\repair\Backup\ServiceState\EventLogs\EventForwarding-Operational.Evt": different creation date/time (set: 3/14/2011 10:34:56 AM, vol: 3/20/2011 4:25:09 PM)

File "C:\WINDOWS\repair\Backup\ServiceState\EventLogs\FwdEvents.Evt": different creation date/time (set: 3/14/2011 10:34:56 AM, vol: 3/20/2011 4:25:09 PM)

File "C:\WINDOWS\repair\Backup\ServiceState\EventLogs\Internet Explorer.evt": different creation date/time (set: 3/14/2011 10:34:56 AM, vol: 3/20/2011 4:25:09 PM)

File "C:\WINDOWS\repair\Backup\ServiceState\EventLogs\kaspersk.evt": different creation date/time (set: 3/14/2011 10:34:56 AM, vol: 3/20/2011 4:25:09 PM)

File "C:\WINDOWS\repair\Backup\ServiceState\EventLogs\NtFrs.Evt": different creation date/time (set: 3/14/2011 10:34:56 AM, vol: 3/20/2011 4:25:09 PM)

File "C:\WINDOWS\repair\Backup\ServiceState\EventLogs\SecEvent.Evt": different creation date/time (set: 3/14/2011 10:34:56 AM, vol: 3/20/2011 4:25:09 PM)

File "C:\WINDOWS\repair\Backup\ServiceState\EventLogs\SysEvent.Evt": different creation date/time (set: 3/14/2011 10:34:56 AM, vol: 3/20/2011 4:25:09 PM)

File "C:\WINDOWS\repair\Backup\ServiceState\EventLogs\WindowsPowerShell.evt": different creation date/time (set: 3/14/2011 10:35:00 AM, vol: 3/20/2011 4:25:11 PM)

File "C:\WINDOWS\SYSMSI\SSEE\MSSQL.2005\MSSQL\LOG\ERRORLOG": different modify date/time (set: 3/20/2011 1:00:55 AM, vol: 3/20/2011 4:25:02 PM)

File "C:\WINDOWS\system32\wbem\Logs\wbemcore.log": different modify date/time (set: 3/20/2011 3:05:54 PM, vol: 3/20/2011 4:25:11 PM)

File "C:\WINDOWS\system32\wbem\Repository\FS\MAPPING.VER": different modify date/time (set: 3/20/2011 3:11:00 PM, vol: 3/20/2011 4:35:32 PM)

3/20/2011 4:39:59 PM: 40 execution errors

Completed: 34021 files, 10.6 GB

Performance: 647.2 MB/minute (495.4 copy, 934.4 compare)

Duration: 00:39:58 (00:06:37 idle/loading/preparing)

 

 

I understand that there are 40 execution errors. We expect this, and it is normal, as our company did not choose to purchase the Open Files backup or SQL database add-ons. Neverless, there was no "corruption" or data from another data set as seen in the first log. I was able to trigger these Recycle backups to successfully occur while looking at the console this morning. This is frowned upon, obviously, since it is occurring during business hours, but the point is, the Recycle backups seem to work, but intermittently with no apparent reason. All of the auto-login credentials for the NAS were set properly, and the System and Application logs for the Administration computer showed nothing out of the ordinary.

 

Suggestions? Help? I'm getting a lot of flak from the bosses about our backups not working on the weekends anymore and I'm out of ideas. I'd also rather not purchase a ASM service account or the $70 one-off tech support fee, as we're a small company and don't have the budget for these things for which we've never had a previous problem until recently, and we've not changed the configurations at all. If I can't get it resolved we're probably going to dump Retrospect and try something a little more reputable.

 

Thanks...

[Mayoff]

Those errors happen because you do not have the open file backup add-on for the non-SQL data. For the SQL data, you need the SQL add-on.

 

Windows will not allow Retrospect to copy these open files, which causes the errors.

 

The -1101 error happens because files have been moved/renamed or deleted during backup.

 

Different creation date/time errors mean the file was copied, but changed during backup.

[wlee]

The information above is very helpful. I have 2 follow up questions:

I am getting the -1101 error but I the file mentioned in the error was open during the backup not moved, renamed, or deleted what other conditions would cause this error?

 

You stated, "Different creation date/time errors mean the file was copied, but changed during backup.". I am also getting this error. Could you clarify what would have changed during the backup? Are the files still intact?

 

In addition I did another backup right after the first back completed and I got the same "different creation date/time" errors again for the same files. Should I expect this every execute a backup?