RESTORE LATEST_ALL never starts
brosato
Posts: 89 Bronze 2
I'm trying to script a restore job using the LATEST_ALL option and it never starts and I don't receive any errors. It's currently been running for 20 minutes and it's a very small database (about 512MB) and there is 35 files, a full, diff and some logs. Here's the command
EXECUTE master..sqlbackup '-SQL "RESTORE DATABASE [ReportServer] FROM DISK = [C:\temp\reportserver\REPORTSERVER*.sqb] LATEST_ALL WITH NORECOVERY"'
EXECUTE master..sqlbackup '-SQL "RESTORE DATABASE [ReportServer] FROM DISK = [C:\temp\reportserver\REPORTSERVER*.sqb] LATEST_ALL WITH NORECOVERY"'
Comments
I suspect that you are using Version 6.4.0.56 of SQL Backup? If the answer is yes, there is a known bug. For some reason the LASTEST_ALL keyword will only work with 10 or less files.
The good news there is a patch that fixes this problem which can be downloaded using this LINK
To apply the patch:
1. Close the SQL Backup GUI. 2. Stop the SQL Backup Agent Service. 3. Locate the exiting 'SQBCoreService.exe' and 'SQLBackupC.exe', by default in the server components install folder, C:\Program Files\Red Gate\SQL Backup 6\(local) or SQL Instance Name. 4. Rename the existing files V6.4.0.56 files, for example to 'OLDSQBCoreService.exe' and 'OLDSQLBackupC.exe' 5. Extract the replacement 'SQBCoreService.exe' and 'SQLBackupC.exe' files from the zip file downloaded and copy them into the installation folder. 6. Restart the SQL Backup Agent service. 7. Ensure that the SQL Backup Agent service starts successfully. 8. Open the SQL Backup GUI, ensure that you obatin a successful connection to the registered server. 9. Perform a test backup and ensure that it is successful. 10. Perform your LATEST_ALL backup.
Any problems, please reply to this forum post.Many Thanks
Eddie
Senior Product Support Engineer
Redgate Software Ltd
Email: support@red-gate.com
SQL error 5069: ALTER DATABASE statement failed.
SQL error 5052: ALTER DATABASE is not permitted while a database is in the Restoring state.
I get this even if I use a full and differential backup generated from the same DB on the same server immediately prior to the restore attempt, as per the script below:
EXEC master..sqlbackup '-SQL "BACKUP DATABASE [FMP] To DISK = [E:\Temp\AMRSQLRepl_FMP_20100707_1536_Full.sqb] WITH CHECKSUM, COMPRESSION=4, KEYSIZE=128, PASSWORD=[pwd], VERIFY"'
GO
EXEC master..sqlbackup '-SQL "BACKUP DATABASE [FMP] To DISK = [E:\Temp\AMRSQLRepl_FMP_20100707_1536_Diff.sqb] WITH DIFFERENTIAL, CHECKSUM, COMPRESSION=4, KEYSIZE=128, PASSWORD=[pwd], VERIFY"'
GO
EXEC master..sqlbackup '-SQL "BACKUP LOG [FMP] To DISK = [E:\Temp\AMRSQLRepl_FMP_20100707_1537_Log.sqb] WITH CHECKSUM, COMPRESSION=4, KEYSIZE=128, PASSWORD=[pwd], VERIFY"'
GO
EXEC master..sqlbackup '-SQL "RESTORE DATABASE [FMP] FROM DISK = [E:\Temp\AMRSQLRepl_FMP*.sqb] LATEST_ALL WITH DISCONNECT_EXISTING, PASSWORD=[pwd], REPLACE"'
GO
All three backup stages completed normally, as did the full restore stage.
SQL server version is 9.0.4053. Script run under the "sa" account.
Suggestions??
Could you please run Profiler, trace the commands that SQL Backup (SQBCoreService.exe) sends to SQL Server, and let me know the full ALTER DATABASE command that's failing?
Thanks.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
---- Test SQL Script ----
USE MASTER
GO
SET NOCOUNT ON
GO
EXEC master..sqlbackup '-SQL "BACKUP DATABASE [FMP] To DISK = [<auto>] WITH CHECKSUM, COMPRESSION=2, KEYSIZE=128, PASSWORD=[TestPwd?!?!], VERIFY"'
GO
select * INTO FMP.dbo.PFMATemp from FMP.dbo.PFMAArea
GO
EXEC master..sqlbackup '-SQL "BACKUP LOG [FMP] To DISK = [<Auto>] WITH CHECKSUM, COMPRESSION=2, KEYSIZE=128, PASSWORD=[TestPwd?!?!], VERIFY"'
--- This LOG backup should be ignored by Latest_All due to the following DIFF.
GO
SELECT *
INTO FMP.dbo.PFMATemp10
FROM FMP.dbo.PFMAArea
WHERE [PFMAArea]='10'
GO
EXEC master..sqlbackup '-SQL "BACKUP DATABASE [FMP] To DISK = [<auto>] WITH DIFFERENTIAL, CHECKSUM, COMPRESSION=2, KEYSIZE=128, PASSWORD=[TestPwd?!?!], VERIFY"'
GO
SELECT *
INTO FMP.dbo.PFMATemp20
FROM FMP.dbo.PFMAArea
WHERE [PFMAArea]='20'
GO
EXEC master..sqlbackup '-SQL "BACKUP LOG [FMP] To DISK = [<Auto>] WITH CHECKSUM, COMPRESSION=2, KEYSIZE=128, PASSWORD=[TestPwd?!?!], VERIFY"'
GO
DROP TABLE FMP.dbo.PFMATemp10
DROP TABLE FMP.dbo.PFMATemp20
DROP TABLE FMP.dbo.PFMATemp
GO
EXEC master..sqlbackup '-SQL "BACKUP LOG [FMP] To DISK = [<Auto>] WITH CHECKSUM, COMPRESSION=2, KEYSIZE=128, PASSWORD=[TestPwd?!?!], VERIFY"'
GO
EXEC master..sqlbackup '-SQL "RESTORE DATABASE [FMP] FROM DISK = [C:\temp\SQLLocalBackup\*FMP*.sqb] LATEST_ALL WITH DISCONNECT_EXISTING, PASSWORD=[TestPwd?!?!], REPLACE"'
GO
USE FMP
GO
---- results of test script ----
SQL Backup v6.4.0.56
Backing up FMP (full database) to:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111055_FULL.sqb
Database size : 145.000 MB
Compressed data size: 466.500 KB
Compression rate : 99.69%
Processed 392 pages for database 'FMP', file 'FMP_Data' on file 1.
Processed 2 pages for database 'FMP', file 'FMP_log' on file 1.
BACKUP DATABASE successfully processed 394 pages in 0.255 seconds (12.629 MB/sec).
Verifying files:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111055_FULL.sqb
The backup set on file 1 is valid.
SQL Backup process ended.
name value
exitcode 0
sqlerrorcode 0
filename001 C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111055_FULL.sqb
SQL Backup v6.4.0.56
Backing up FMP (transaction log) to:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111058_LOG.sqb
Backup data size : 640.000 KB
Compressed data size: 21.000 KB
Compression rate : 96.72%
Processed 8 pages for database 'FMP', file 'FMP_log' on file 1.
BACKUP LOG successfully processed 8 pages in 0.025 seconds (2.314 MB/sec).
Verifying files:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111058_LOG.sqb
The backup set on file 1 is valid.
SQL Backup process ended.
name value
exitcode 0
sqlerrorcode 0
filename001 C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111058_LOG.sqb
SQL Backup v6.4.0.56
Backing up FMP (differential database) to:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111103_DIFF.sqb
Backup data size : 2.688 MB
Compressed data size: 186.000 KB
Compression rate : 93.24%
Processed 144 pages for database 'FMP', file 'FMP_Data' on file 1.
Processed 5 pages for database 'FMP', file 'FMP_log' on file 1.
BACKUP DATABASE WITH DIFFERENTIAL successfully processed 149 pages in 0.134 seconds (9.066 MB/sec).
Verifying files:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111103_DIFF.sqb
The backup set on file 1 is valid.
SQL Backup process ended.
name value
exitcode 0
sqlerrorcode 0
filename001 C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111103_DIFF.sqb
SQL Backup v6.4.0.56
Backing up FMP (transaction log) to:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111105_LOG.sqb
Backup data size : 640.000 KB
Compressed data size: 17.500 KB
Compression rate : 97.27%
Processed 7 pages for database 'FMP', file 'FMP_log' on file 1.
BACKUP LOG successfully processed 7 pages in 0.020 seconds (2.560 MB/sec).
Verifying files:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111105_LOG.sqb
The backup set on file 1 is valid.
SQL Backup process ended.
name value
exitcode 0
sqlerrorcode 0
filename001 C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111105_LOG.sqb
SQL Backup v6.4.0.56
Backing up FMP (transaction log) to:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111108_LOG.sqb
Backup data size : 640.000 KB
Compressed data size: 14.000 KB
Compression rate : 97.81%
Processed 3 pages for database 'FMP', file 'FMP_log' on file 1.
BACKUP LOG successfully processed 3 pages in 0.026 seconds (0.689 MB/sec).
Verifying files:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111108_LOG.sqb
The backup set on file 1 is valid.
SQL Backup process ended.
name value
exitcode 0
sqlerrorcode 0
filename001 C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111108_LOG.sqb
SQL Backup v6.4.0.56
Restoring FMP (database) from:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111055_FULL.sqb
Processed 392 pages for database 'FMP', file 'FMP_Data' on file 1.
Processed 2 pages for database 'FMP', file 'FMP_log' on file 1.
RESTORE DATABASE successfully processed 394 pages in 1.445 seconds (2.228 MB/sec).
Restoring FMP (database) from:
C:\temp\SQLLocalBackup\AMRSQLREPL_(local)_FMP_20100709_111103_DIFF.sqb
Processed 144 pages for database 'FMP', file 'FMP_Data' on file 1.
Processed 5 pages for database 'FMP', file 'FMP_log' on file 1.
RESTORE DATABASE successfully processed 149 pages in 1.528 seconds (0.795 MB/sec).
SQL Backup process ended.
name value
exitcode 0
sqlerrorcode 0
Msg 927, Level 14, State 2, Line 2
Database 'FMP' cannot be opened. It is in the middle of a restore.
>> Database 'FMP' cannot be opened. It is in the middle of a restore.
This last error suggests that there is still something wrong with SQL Backup trying to access the database in an invalid manner. Could you please run Profiler and trace what was the last action attempted by the SQL Backup Agent service? You can filter on the application name SQBCoreService.exe.
Thanks.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
I will "re-install" the 1001 files and try testing again, but I will have to set up a designated test server with a trial install to do so - no more "testing" on our production hot-spare log shipping system!
In the Latest_all attempt that fails, the last action attempted by the SQBCoreService process is the first log restore (from a set of 3 virtual devices) after the database restores for, presummably, the preceeding full and differential backups, also from sets of virtual devices.
Are you guys also using the patched version, as the official 6.4.0.56 version has a known bug where it doesn't attempt to check more than 10 transaction log files in a directory?
Thanks.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
When you use just the LATEST_ALL option, SQL Backup attempts to sort the files based on the header details contained in each file. With regards to your test where only the full and differential backups were applied, but not the transaction log backups, could you please run RESTORE SQBHEADERONLY on each of those files (for the trx log files, just the first couple of files would do) e.g.
and post the following details for each of those files:
Backup start
Backup finish
First LSN
Last LSN
Checkpoint LSN
Differential base LSN
Also, please check if the 'Server name' and 'Database name' values are consistent.
Thanks.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
Backup start : 7/29/2010 10:15:05 AM
Backup finish: 7/29/2010 10:15:05 AM
First LSN : 16630000000491400001
Last LSN : 16630000000491600001
Checkpoint LSN : 16630000000491400001
Database backup LSN : 16603000000066900038
Differential base LSN : NULL
Backup start : 7/29/2010 10:30:04 AM
Backup finish: 7/29/2010 10:30:04 AM
First LSN : 16630000000491600001
Last LSN : 16630000000491900001
Checkpoint LSN : 16630000000491400001
Database backup LSN : 16603000000066900038
Differential base LSN : NULL
Backup start : 7/29/2010 10:38:17 AM
Backup finish: 7/29/2010 10:38:17 AM
First LSN : 16630000000491900001
Last LSN : 16630000000585500001
Checkpoint LSN : 16630000000491400001
Database backup LSN : 16603000000066900038
Differential base LSN : NULL
Thanks.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
Backup finish: 7/25/2010 2:30:24 AM
First LSN : 16603000000066900038
Last LSN : 16603000000069100001
Checkpoint LSN : 16603000000066900038
Database backup LSN : 16479000000778900038
Differential base LSN : NULL
Backup start : 7/29/2010 10:02:02 AM
Backup finish: 7/29/2010 10:02:04 AM
First LSN : 16630000000491400001
Last LSN : 16630000000491600001
Checkpoint LSN : 16630000000491400001
Database backup LSN : 16603000000066900038
Differential base LSN : 16603000000066900038
SQL Backup process ended.
EXEC master.dbo.sqlbackup '-SQL "RESTORE DATABASE Ektron FROM DISK = [\\Recovery\SQLBackups\Thor\Ektron\*.sqb] LATEST_ALL with MAILTO = [me@mycompany.com],RECOVERY,REPLACE, SINGLERESULTSET, PASSWORD = [Password], MOVE [EverestEktronDev_log] TO [C:\TEMP\Ektron_log.ldf], move [EverestEktronDev] to [C:\temp\Ektron.mdf]" -I dba'
Restoring Ektron (database) on dba instance from:
\\Recovery\SQLBackups\Thor\Ektron\FULL_20100725_023013.sqb
Processed 102840 pages for database 'Ektron', file 'EverestEktronDev' on file 1.
Processed 2 pages for database 'Ektron', file 'EverestEktronDev_log' on file 1.
RESTORE DATABASE successfully processed 102842 pages in 117.873 seconds (6.816 MB/sec).
Restoring Ektron (database) on dba instance from:
\\Recovery\SQLBackups\Thor\Ektron\DIFF_Ektron_20100730_023011.sqb
Processed 7384 pages for database 'Ektron', file 'EverestEktronDev' on file 1.
Processed 1 pages for database 'Ektron', file 'EverestEktronDev_log' on file 1.
RESTORE DATABASE successfully processed 7385 pages in 46.030 seconds (1.253 MB/sec).
Restoring Ektron (transaction logs) on dba instance from:
\\Recovery\SQLBackups\Thor\Ektron\LOG_Ektron_20100730_064503.sqb
Thread 0 error:
Process terminated unexpectedly. Error code: -2139684860 (An abort request is preventing anything except termination actions.)
Thread 1 error:
Process terminated unexpectedly. Error code: -2139684860 (An abort request is preventing anything except termination actions.)
Thread 2 error:
Process terminated unexpectedly. Error code: -2139684860 (An abort request is preventing anything except termination actions.)
Thread 3 error:
Process terminated unexpectedly. Error code: -2139684860 (An abort request is preventing anything except termination actions.)
Thread 4 error:
Process terminated unexpectedly. Error code: -2139684860 (An abort request is preventing anything except termination actions.)
Thread 5 error:
Process terminated unexpectedly. Error code: -2139684860 (An abort request is preventing anything except termination actions.)
Thread 6 error:
Process terminated unexpectedly. Error code: -2139684860 (An abort request is preventing anything except termination actions.)
Thread 7 error:
Process terminated unexpectedly. Error code: -2139684860 (An abort request is preventing anything except termination actions.)
Thread 8 error:
Process terminated unexpectedly. Error code: -2139684860 (An abort request is preventing anything except termination actions.)
Thread 9 error:
Process terminated unexpectedly. Error code: -2139684860 (An abort request is preventing anything except termination actions.)
Thread 10 error:
Process terminated unexpectedly. Error code: -2139684860 (An abort request is preventing anything except termination actions.)
SQL error 3013: SQL error 3013: RESTORE LOG is terminating abnormally.
SQL error 4305: SQL error 4305: The log in this backup set begins at LSN 16634000000669900001, which is too recent to apply to the database. An earlier log backup that includes LSN 16634000000591800001 can be restored.
SQL Backup exit code: 790
SQL error code: 4305
I am just using LATEST_ALL as I am restoring to a different server from the backup source (i.e. moving production data to a test system etc).
Here are the headers for the full and differential backup files, the first two and last skipped log backup files, plus the log file the process tried to restore out of sequence. There were 13 log backup files skipped in total.
FULL header:
Server name : AMRSQL1
Database name : AMRAudit
Machine name : AMRSQL1
Backup start : 27/07/2010 02:09:55
Backup finish: 27/07/2010 02:10:50
First LSN : 3251000000365000072
Last LSN : 3251000000368000001
Checkpoint LSN : 3251000000365000072
Database backup LSN : 3230000000416500072
Differential base LSN : NULL
DIFFERENTIAL header:
Server name : AMRSQL1
Database name : AMRAudit
Machine name : AMRSQL1
Backup start : 29/07/2010 02:07:16
Backup finish: 29/07/2010 02:07:17
First LSN : 3251000000427900035
Last LSN : 3251000000429400001
Checkpoint LSN : 3251000000427900035
Database backup LSN : 3251000000365000072
Differential base LSN : 3251000000365000072
First skipped LOG header:
Server name : AMRSQL1
Database name : AMRAudit
Machine name : AMRSQL1
Backup start : 29/07/2010 05:05:03
Backup finish: 29/07/2010 05:05:03
First LSN : 3251000000427900001
Last LSN : 3251000000429400001
Checkpoint LSN : 3251000000427900035
Database backup LSN : 3251000000365000072
Differential base LSN : NULL
Second skipped LOG header:
Server name : AMRSQL1
Database name : AMRAudit
Machine name : AMRSQL1
Backup start : 29/07/2010 05:25:03
Backup finish: 29/07/2010 05:25:03
First LSN : 3251000000429400001
Last LSN : 3251000000429400001
Checkpoint LSN : 3251000000427900035
Database backup LSN : 3251000000365000072
Differential base LSN : NULL
Last skipped LOG header:
Server name : AMRSQL1
Database name : AMRAudit
Machine name : AMRSQL1
Backup start : 29/07/2010 09:05:05
Backup finish: 29/07/2010 09:05:05
First LSN : 3251000000433300001
Last LSN : 3251000000433900001
Checkpoint LSN : 3251000000427900035
Database backup LSN : 3251000000365000072
Differential base LSN : NULL
First LOG Restore attempt - header:
Server name : AMRSQL1
Database name : AMRAudit
Machine name : AMRSQL1
Backup start : 29/07/2010 09:25:04
Backup finish: 29/07/2010 09:25:04
First LSN : 3251000000433900001
Last LSN : 3251000000434500001
Checkpoint LSN : 3251000000427900035
Database backup LSN : 3251000000365000072
Differential base LSN : NULL
Error message from Log Restore Attempt:
SQL error 3013: SQL error 3013: RESTORE LOG is terminating abnormally.
SQL error 4305: SQL error 4305: The log in this backup set begins at LSN 3251000000433900001, which is too recent to apply to the database. An earlier log backup that includes LSN 3251000000429400001 can be restored.
The restore attempt was done on the dev/test server using the patched 6.4.0.1001 files. When I initially tried this with the unpatched .56 release, the restore attempt would never start at all as per the >10 files bug.
Not so easy after all!
This is indeed a bug, guys, thanks for reporting it. Could you please download the 6.4.0.1013 patch, and check if it fixes the issue? You can download it using the following URL:
ftp://support.red-gate.com/patches/sql_ ... 0_1013.zip
That archive contains the patched SQL Backup Agent executable file (SQBCoreService.exe), and command line interface (SQLBackupC.exe). To replace the existing SQL Backup Agent file, do the following:
- ensure that no SQL Backup processes are running
- stop the SQL Backup Agent service, or if on a cluster resource, disable the resource then stop it
- rename the existing executable file
- extract and place the patched executable file into the same folder
- restart the SQL Backup Agent service/cluster resource
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
Thanks for your help and THANK YOU for a great set of products in the SQL Toolkit. Backup is great, while Compare and DataCompare are absolutely essential to me now.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
Thanks.