running the upgrade step from version 610 to version 611 fails

I am having an intermittent problem when restoring a SQL Server 2000 database to SQL Server 2005.

I have a job that runs daily that restores the database. This job has ran 20 times with no problem and has failed twice. When it fails it fails in the exact same place with the same error message:

>>Restoring Backup File: D:\Backups\Production\IHI.bak [SQLSTATE 01000]
Processed 388880 pages for database 'IHI', file 'IHIDat.mdf' on file 1. [SQLSTATE 01000]
Processed 1 pages for database 'IHI', file 'IHILog.ldf' on file 1. [SQLSTATE 01000]
RESTORE DATABASE successfully processed 388881 pages in 130.732 seconds (24.368 MB/sec). [SQLSTATE 01000]
>>Bringing database online... [SQLSTATE 01000]
Converting database 'IHI' from version 539 to the current version 611. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 539 to version 551. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 551 to version 552. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 552 to version 553. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 553 to version 554. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 554 to version 589. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 589 to version 590. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 590 to version 593. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 593 to version 597. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 597 to version 604. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 604 to version 605. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 605 to version 606. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 606 to version 607. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 607 to version 608. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 608 to version 609. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 609 to version 610. [SQLSTATE 01000]
Msg 3023, Sev 16, State 3, Line 1 : Backup and file manipulation operations (such as ALTER DATABASE ADD FILE) on a database must be serialized. Reissue the statement after the current backup or file manipulation operation is completed. [SQLSTATE 42000]
Msg 5069, Sev 16, State 1, Line 1 : ALTER DATABASE statement failed. [SQLSTATE 42000]
Msg 951, Sev 16, State 1, Line 287 : Database 'IHI' running the upgrade step from version 610 to version 611. [SQLSTATE 01000]
Msg 3014, Sev 16, State 1, Line 287 : RESTORE DATABASE successfully processed 0 pages in 30.370 seconds (0.000 MB/sec). [SQLSTATE 01000]

For some reason the last step of upgrading to 611 seems to be having a problem. If I rerun the job on the exact same IHI.bak 10 minutes later it will/has succeeded. So I don't particulary think there is a problem with the .bak it self.

Anyone have any ideas?

-Mark

I think there is some reordering of error messages here by the client that is confusing things some, but the 5069 error you are getting should only come from an ALTER DATABASE command, not the RESTORE, and that seems to be failing. Is your job doing some kind of option or state change on the DB after the RESTORE? Can you post a fragment of the errorlog around the time of such a failure?

|||

At 6AM the Job started which refreshes numerous databases. Three of these DBs are from 2000 server: DYNAMICS, IHI, and SBM01. All the others are from a 2005 server.

The Job was re-ran at 7:14 on the same day and completed successfully. The 6am job failed.

SQL Error Log:

01/28/2007 07:40:52,spid57,Unknown,Setting database option RECOVERY to SIMPLE for database SBM01.
01/28/2007 07:40:25,spid57,Unknown,Recovery is writing a checkpoint in database 'SBM01' (7). This is an informational message only. No user action is required.
01/28/2007 07:40:25,spid57,Unknown,Starting up database 'SBM01'.
01/28/2007 07:40:25,Backup,Unknown,Database was restored: Database: SBM01<c/> creation date(time): 2005/01/04(11:36:34)<c/> first LSN: 3943:4917:1<c/> last LSN: 3943:4922:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\SBM01.bak'}). Informational message. No user action required.
01/28/2007 07:40:25,spid57,Unknown,The database 'SBM01' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 07:40:25,spid57,Unknown,Starting up database 'SBM01'.
01/28/2007 07:40:03,spid57,Unknown,The database 'SBM01' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 07:40:02,spid57,Unknown,Starting up database 'SBM01'.
01/28/2007 07:40:01,spid57,Unknown,Setting database option OFFLINE to ON for database SBM01.
01/28/2007 07:36:03,spid57,Unknown,Setting database option RECOVERY to SIMPLE for database IHI.
01/28/2007 07:35:33,spid57,Unknown,Recovery is writing a checkpoint in database 'IHI' (5). This is an informational message only. No user action is required.
01/28/2007 07:35:31,spid57,Unknown,Starting up database 'IHI'.
01/28/2007 07:35:31,Backup,Unknown,Database was restored: Database: IHI<c/> creation date(time): 2003/07/22(11:29:55)<c/> first LSN: 17290:32:1<c/> last LSN: 17290:45:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\IHI.bak'}). Informational message. No user action required.
01/28/2007 07:35:31,spid57,Unknown,The database 'IHI' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 07:35:31,spid57,Unknown,Starting up database 'IHI'.
01/28/2007 07:33:21,spid57,Unknown,The database 'IHI' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 07:33:20,spid57,Unknown,Starting up database 'IHI'.
01/28/2007 07:33:20,spid57,Unknown,Setting database option OFFLINE to ON for database IHI.
01/28/2007 07:33:17,spid57,Unknown,Setting database option RECOVERY to SIMPLE for database DYNAMICS.
01/28/2007 07:33:14,spid57,Unknown,Recovery is writing a checkpoint in database 'DYNAMICS' (6). This is an informational message only. No user action is required.
01/28/2007 07:33:14,spid57,Unknown,Starting up database 'DYNAMICS'.
01/28/2007 07:33:14,Backup,Unknown,Database was restored: Database: DYNAMICS<c/> creation date(time): 2003/07/22(11:20:05)<c/> first LSN: 579:34:1<c/> last LSN: 579:36:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\DYNAMICS.bak'}). Informational message. No user action required.
01/28/2007 07:33:14,spid57,Unknown,The database 'DYNAMICS' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 07:33:14,spid57,Unknown,Starting up database 'DYNAMICS'.
01/28/2007 07:33:09,spid57,Unknown,The database 'DYNAMICS' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 07:33:09,spid57,Unknown,Starting up database 'DYNAMICS'.
01/28/2007 07:33:09,spid57,Unknown,Setting database option OFFLINE to ON for database DYNAMICS.
01/28/2007 07:33:08,spid57,Unknown,Setting database option RECOVERY to SIMPLE for database DW_EventStats.
01/28/2007 07:33:08,spid57,Unknown,Starting up database 'DW_EventStats'.
01/28/2007 07:33:08,Backup,Unknown,Database was restored: Database: DW_EventStats<c/> creation date(time): 2006/02/25(10:37:46)<c/> first LSN: 569:307:37<c/> last LSN: 569:323:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\PROD_EventStats.bak'}). Informational message. No user action required.
01/28/2007 07:33:08,spid57,Unknown,The database 'DW_EventStats' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 07:33:08,spid57,Unknown,Starting up database 'DW_EventStats'.
01/28/2007 07:33:08,spid57,Unknown,The database 'DW_EventStats' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 07:33:08,spid57,Unknown,Starting up database 'DW_EventStats'.
01/28/2007 07:33:07,spid57,Unknown,Setting database option OFFLINE to ON for database DW_EventStats.
01/28/2007 07:30:01,Backup,Unknown,Log was backed up. Database: IHI<c/> creation date(time): 2007/01/17(09:44:21)<c/> first LSN: 17445:99857:1<c/> last LSN: 17445:99857:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'S:\backup\IHI\IHI_20070128073001257_S.trn'}). This is an informational message only. No user action is required.
01/28/2007 07:25:16,spid57,Unknown,Setting database option RECOVERY to SIMPLE for database DW_IHIDB.
01/28/2007 07:25:15,spid57,Unknown,Starting up database 'DW_IHIDB'.
01/28/2007 07:25:15,Backup,Unknown,Database was restored: Database: DW_IHIDB<c/> creation date(time): 2006/02/25(10:41:52)<c/> first LSN: 78692:11007:261<c/> last LSN: 78692:11114:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\PROD_IHIDB.bak'}). Informational message. No user action required.
01/28/2007 07:25:13,spid57,Unknown,The database 'DW_IHIDB' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 07:25:13,spid57,Unknown,Starting up database 'DW_IHIDB'.
01/28/2007 07:22:05,spid57,Unknown,The database 'DW_IHIDB' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 07:22:05,spid57,Unknown,Starting up database 'DW_IHIDB'.
01/28/2007 07:22:05,spid57,Unknown,Setting database option OFFLINE to ON for database DW_IHIDB.
01/28/2007 07:22:05,spid57,Unknown,Setting database option RECOVERY to SIMPLE for database DW_NEventStats.
01/28/2007 07:22:05,spid57,Unknown,Starting up database 'DW_NEventStats'.
01/28/2007 07:22:05,Backup,Unknown,Database was restored: Database: DW_NEventStats<c/> creation date(time): 2006/02/25(10:53:08)<c/> first LSN: 252:570:81<c/> last LSN: 252:603:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\PROD_NEventStats.bak'}). Informational message. No user action required.
01/28/2007 07:22:05,spid57,Unknown,The database 'DW_NEventStats' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 07:22:05,spid57,Unknown,Starting up database 'DW_NEventStats'.
01/28/2007 07:22:04,spid57,Unknown,The database 'DW_NEventStats' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 07:22:04,spid57,Unknown,Starting up database 'DW_NEventStats'.
01/28/2007 07:22:04,spid57,Unknown,Setting database option OFFLINE to ON for database DW_NEventStats.
01/28/2007 07:21:10,spid57,Unknown,Setting database option RECOVERY to SIMPLE for database DW_NICHQDB.
01/28/2007 07:21:07,spid57,Unknown,Starting up database 'DW_NICHQDB'.
01/28/2007 07:21:07,Backup,Unknown,Database was restored: Database: DW_NICHQDB<c/> creation date(time): 2006/02/25(10:54:06)<c/> first LSN: 5137:438:99<c/> last LSN: 5137:479:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\PROD_NICHQDB.bak'}). Informational message. No user action required.
01/28/2007 07:21:06,spid57,Unknown,The database 'DW_NICHQDB' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 07:21:06,spid57,Unknown,Starting up database 'DW_NICHQDB'.
01/28/2007 07:20:37,spid57,Unknown,The database 'DW_NICHQDB' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 07:20:37,spid57,Unknown,Starting up database 'DW_NICHQDB'.
01/28/2007 07:20:37,spid57,Unknown,Setting database option OFFLINE to ON for database DW_NICHQDB.
01/28/2007 07:15:01,Backup,Unknown,Log was backed up. Database: IHI<c/> creation date(time): 2007/01/17(09:44:21)<c/> first LSN: 17445:99857:1<c/> last LSN: 17445:99857:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'S:\backup\IHI\IHI_20070128071501527_S.trn'}). This is an informational message only. No user action is required.
01/28/2007 07:14:44,spid56,Unknown,Recovery is writing a checkpoint in database 'SBM01' (7). This is an informational message only. No user action is required.
01/28/2007 07:14:44,spid56,Unknown,0 transactions rolled back in database 'SBM01' (7). This is an informational message only. No user action is required.
01/28/2007 07:14:44,spid56,Unknown,1 transactions rolled forward in database 'SBM01' (7). This is an informational message only. No user action is required.
01/28/2007 07:14:44,spid56,Unknown,Starting up database 'SBM01'.
01/28/2007 07:14:44,spid56,Unknown,Setting database option ONLINE to ON for database SBM01.
01/28/2007 07:00:00,Backup,Unknown,Log was backed up. Database: IHI<c/> creation date(time): 2007/01/17(09:44:21)<c/> first LSN: 17445:99857:1<c/> last LSN: 17445:99857:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'S:\backup\IHI\IHI_20070128070000313_S.trn'}). This is an informational message only. No user action is required.
01/28/2007 06:45:00,Backup,Unknown,Log was backed up. Database: IHI<c/> creation date(time): 2007/01/17(09:44:21)<c/> first LSN: 17445:99824:1<c/> last LSN: 17445:99857:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'S:\backup\IHI\IHI_20070128064500223_S.trn'}). This is an informational message only. No user action is required.
01/28/2007 06:31:04,Backup,Unknown,Log was backed up. Database: IHI<c/> creation date(time): 2007/01/17(09:44:21)<c/> first LSN: 17328:5750:1<c/> last LSN: 17445:99824:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'S:\backup\IHI\IHI_20070128063000540_S.trn'}). This is an informational message only. No user action is required.
01/28/2007 06:19:37,spid55,Unknown,Setting database option OFFLINE to ON for database SBM01.
01/28/2007 06:15:25,Backup,Unknown,Log was backed up. Database: IHI<c/> creation date(time): 2007/01/17(09:44:21)<c/> first LSN: 17290:45:1<c/> last LSN: 17328:5750:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'S:\backup\IHI\IHI_20070128061502183_S.trn'}). This is an informational message only. No user action is required.
01/28/2007 06:15:22,spid55,Unknown,Setting database option RECOVERY to SIMPLE for database IHI.
01/28/2007 06:14:51,spid55,Unknown,Recovery is writing a checkpoint in database 'IHI' (5). This is an informational message only. No user action is required.
01/28/2007 06:14:51,spid55,Unknown,Starting up database 'IHI'.
01/28/2007 06:14:51,Backup,Unknown,Database was restored: Database: IHI<c/> creation date(time): 2003/07/22(11:29:55)<c/> first LSN: 17290:32:1<c/> last LSN: 17290:45:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\IHI.bak'}). Informational message. No user action required.
01/28/2007 06:14:50,spid55,Unknown,The database 'IHI' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 06:14:50,spid55,Unknown,Starting up database 'IHI'.
01/28/2007 06:12:39,spid55,Unknown,The database 'IHI' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 06:12:39,spid55,Unknown,Starting up database 'IHI'.
01/28/2007 06:12:39,spid55,Unknown,Setting database option OFFLINE to ON for database IHI.
01/28/2007 06:12:37,spid55,Unknown,Setting database option RECOVERY to SIMPLE for database DYNAMICS.
01/28/2007 06:12:34,spid55,Unknown,Recovery is writing a checkpoint in database 'DYNAMICS' (6). This is an informational message only. No user action is required.
01/28/2007 06:12:34,spid55,Unknown,Starting up database 'DYNAMICS'.
01/28/2007 06:12:34,Backup,Unknown,Database was restored: Database: DYNAMICS<c/> creation date(time): 2003/07/22(11:20:05)<c/> first LSN: 579:34:1<c/> last LSN: 579:36:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\DYNAMICS.bak'}). Informational message. No user action required.
01/28/2007 06:12:33,spid55,Unknown,The database 'DYNAMICS' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 06:12:33,spid55,Unknown,Starting up database 'DYNAMICS'.
01/28/2007 06:12:28,spid55,Unknown,The database 'DYNAMICS' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 06:12:28,spid55,Unknown,Starting up database 'DYNAMICS'.
01/28/2007 06:12:27,spid55,Unknown,Setting database option OFFLINE to ON for database DYNAMICS.
01/28/2007 06:12:27,spid55,Unknown,Setting database option RECOVERY to SIMPLE for database DW_EventStats.
01/28/2007 06:12:27,spid55,Unknown,Starting up database 'DW_EventStats'.
01/28/2007 06:12:27,Backup,Unknown,Database was restored: Database: DW_EventStats<c/> creation date(time): 2006/02/25(10:37:46)<c/> first LSN: 569:307:37<c/> last LSN: 569:323:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\PROD_EventStats.bak'}). Informational message. No user action required.
01/28/2007 06:12:27,spid55,Unknown,The database 'DW_EventStats' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 06:12:27,spid55,Unknown,Starting up database 'DW_EventStats'.
01/28/2007 06:12:26,spid55,Unknown,The database 'DW_EventStats' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 06:12:26,spid55,Unknown,Starting up database 'DW_EventStats'.
01/28/2007 06:12:26,spid55,Unknown,Setting database option OFFLINE to ON for database DW_EventStats.
01/28/2007 06:04:43,spid55,Unknown,Setting database option RECOVERY to SIMPLE for database DW_IHIDB.
01/28/2007 06:04:42,spid55,Unknown,Starting up database 'DW_IHIDB'.
01/28/2007 06:04:42,Backup,Unknown,Database was restored: Database: DW_IHIDB<c/> creation date(time): 2006/02/25(10:41:52)<c/> first LSN: 78692:11007:261<c/> last LSN: 78692:11114:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\PROD_IHIDB.bak'}). Informational message. No user action required.
01/28/2007 06:04:40,spid55,Unknown,The database 'DW_IHIDB' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 06:04:40,spid55,Unknown,Starting up database 'DW_IHIDB'.
01/28/2007 06:01:31,spid55,Unknown,The database 'DW_IHIDB' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 06:01:30,spid55,Unknown,Starting up database 'DW_IHIDB'.
01/28/2007 06:01:30,spid55,Unknown,Setting database option OFFLINE to ON for database DW_IHIDB.
01/28/2007 06:01:30,spid55,Unknown,Setting database option RECOVERY to SIMPLE for database DW_NEventStats.
01/28/2007 06:01:30,spid55,Unknown,Starting up database 'DW_NEventStats'.
01/28/2007 06:01:30,Backup,Unknown,Database was restored: Database: DW_NEventStats<c/> creation date(time): 2006/02/25(10:53:08)<c/> first LSN: 252:570:81<c/> last LSN: 252:603:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\PROD_NEventStats.bak'}). Informational message. No user action required.
01/28/2007 06:01:30,spid55,Unknown,The database 'DW_NEventStats' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 06:01:30,spid55,Unknown,Starting up database 'DW_NEventStats'.
01/28/2007 06:01:29,spid55,Unknown,The database 'DW_NEventStats' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 06:01:29,spid55,Unknown,Starting up database 'DW_NEventStats'.
01/28/2007 06:01:29,spid55,Unknown,Setting database option OFFLINE to ON for database DW_NEventStats.
01/28/2007 06:00:33,spid55,Unknown,Setting database option RECOVERY to SIMPLE for database DW_NICHQDB.
01/28/2007 06:00:31,spid55,Unknown,Starting up database 'DW_NICHQDB'.
01/28/2007 06:00:31,Backup,Unknown,Database was restored: Database: DW_NICHQDB<c/> creation date(time): 2006/02/25(10:54:06)<c/> first LSN: 5137:438:99<c/> last LSN: 5137:479:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'D:\Backups\Production\PROD_NICHQDB.bak'}). Informational message. No user action required.
01/28/2007 06:00:30,spid55,Unknown,The database 'DW_NICHQDB' is marked RESTORING and is in a state that does not allow recovery to be run.
01/28/2007 06:00:30,spid55,Unknown,Starting up database 'DW_NICHQDB'.
01/28/2007 06:00:01,spid55,Unknown,The database 'DW_NICHQDB' is marked OFFLINE and is in a state that does not allow recovery to be run.
01/28/2007 06:00:01,spid55,Unknown,Starting up database 'DW_NICHQDB'.
01/28/2007 06:00:01,spid55,Unknown,Setting database option OFFLINE to ON for database DW_NICHQDB.

What I had posted earlier was the output from the Job.

My restore process is:

'ALTER DATABASE ' + @.database + ' SET OFFLINE WITH ROLLBACK IMMEDIATE'
RESTORE DATABASE @.database FROM DISK = @.fileBAK WITH FILE = 1, MOVE @.backupMDFName TO @.dbMDFFile, MOVE @.backupLDFName O @.dbLDFFile, NORECOVERY, REPLACE
RESTORE DATABASE @.database FROM DISK = @.fileDFF WITH FILE = 1, MOVE @.backupMDFName TO @.dbMDFFile, MOVE @.backupLDFName O @.dbLDFFile, NORECOVERY, REPLACE
RESTORE DATABASE @.database WITH RECOVERY

I then change the owner, fix users, change recovery model to SIMPLE, and finally shrink the DB.

What I find strange is that this works almost all of the time. In the case of the error log above the job completed successfully the second time it ran 40 minutes later. What would cause it to fail. I haven't had any issues with the 2005 databases and they all to through the exact same steps.

Here is an excerpt from the job log where it completed successfully for the IHI DB today:

>>Restoring: 6=IHI [SQLSTATE 01000]
DATABASE: IHI [SQLSTATE 01000]
PATH: D:\Backups\Production [SQLSTATE 01000]
FILE: IHI [SQLSTATE 01000]
>>Taking the database offline... [SQLSTATE 01000]
>>Restoring Backup File: D:\Backups\Production\IHI.bak [SQLSTATE 01000]
Processed 390848 pages for database 'IHI', file 'IHIDat.mdf' on file 1. [SQLSTATE 01000]
Processed 3 pages for database 'IHI', file 'IHILog.ldf' on file 1. [SQLSTATE 01000]
RESTORE DATABASE successfully processed 390851 pages in 126.707 seconds (25.269 MB/sec). [SQLSTATE 01000]
>>Bringing database online... [SQLSTATE 01000]
Converting database 'IHI' from version 539 to the current version 611. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 539 to version 551. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 551 to version 552. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 552 to version 553. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 553 to version 554. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 554 to version 589. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 589 to version 590. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 590 to version 593. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 593 to version 597. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 597 to version 604. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 604 to version 605. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 605 to version 606. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 606 to version 607. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 607 to version 608. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 608 to version 609. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 609 to version 610. [SQLSTATE 01000]
Database 'IHI' running the upgrade step from version 610 to version 611. [SQLSTATE 01000]
RESTORE DATABASE successfully processed 0 pages in 29.169 seconds (0.000 MB/sec). [SQLSTATE 01000]
>>Changing owner to sa... [SQLSTATE 01000]
>>Fixing user account: mark [SQLSTATE 01000]
The row for user 'mark' will be fixed by updating its login link to a login already in existence. [SQLSTATE 01000]
The number of orphaned users fixed by updating users was 1. [SQLSTATE 01000]
The number of orphaned users fixed by adding new logins and then updating users was 0. [SQLSTATE 01000]
USE IHI; EXEC sp_change_users_login 'Auto_Fix', 'mark' [SQLSTATE 01000]
>>Changing Recovery Model to SIMPLE... [SQLSTATE 01000]
>>Shrinking the database... [SQLSTATE 01000]

Thanks, -Mark

|||

These two lines are interesting. I'm going to reverse them so they are in chronological order

...

01/28/2007 06:15:22,spid55,Unknown,Setting database option RECOVERY to SIMPLE for database IHI.
01/28/2007 06:15:25,Backup,Unknown,Log was backed up. Database: IHI<c/> creation date(time): 2007/01/17(09:44:21)<c/> first LSN: 17290:45:1<c/> last LSN: 17328:5750:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'S:\backup\IHI\IHI_20070128061502183_S.trn'}). This is an informational message only. No user action is required.
...

The first line actually gets output before we attempt the ALTER DATABASE operation. Do you have some kind of background process that goes through and does log backups on databases that are in FULL recovery mode? It looks like what is happening is that your ALTER DATABASE SET RECOVERY SIMPLE is failing because it is colliding with some other thread that is doing a BACKUP LOG at the same time. Is that possible?

|||

That is very possible. Since I convert these DBs to SIMPLE as part of the restore operation I didn't even really notice that the error log said a log was being taken.

This server has several custom jobs that our Datacenter host provides and supports that does daily backups along with 15 minute transaction logs. I convert these DBs to SIMPLE since we are only using them for reporting purposes on this server and I don't need to have the extra overhead with the backups.

When I am restoring the DB it is in FULL recovery mode since that is how it is on the production server we are copying from. During the restore operation the 15 minute backup is occasionally colliding with my restore causing the problem. All makes perfect sense now.

I never considered that job potentially being issue since for one I didn't create it and manage it and the other being that I know I put everything into SIMPLE which is skipped by that job.

I will work with my host to resolve the timing of my restores.

Thanks for your help. I definitelly needed another set of eyes.

-Mark