Why is RESTORE LOG failing?

NicolasNicolas Posts: 10
edited December 2, 2010 7:53AM in SQL Backup Previous Versions
Hi, any clue as to why the below RESTORE LOG is failing?
We're on SQL Backup 6.4.0.56
I can't see that there's anything wrong with our code. It seems Redgate is doing something in the wrong order?

DECLARE
@exitcode int,
@sqlerrorcode int,
@DBN varchar(200),
@Server varchar(100),
@CMD nvarchar(4000),
@Datum nvarchar (8),
@Tijd nvarchar (8)

SET @DBN = 'PROD_00033486'
SET @Server = 'RLZ-DB11'
SET @Datum = '20101130'
SET @Tijd = '08:00'

SET @CMD = '-SQL "RESTORE DATABASE '+@DBN+
' FROM DISK = ''\\rlz-filer1\'+@Server+'\RedgateBackup\Prod\'+@DBN+'\'+@DBN+'_'+@Datum+'*.FULL.sqb'''+
' WITH NORECOVERY,'+
' REPLACE,'+
' DISCONNECT_EXISTING"'
EXECUTE master..sqlbackup @CMD, @exitcode OUT, @sqlerrorcode OUT

SET @CMD = '-SQL "RESTORE LOG '+@DBN+
' FROM DISK = ''\\rlz-filer1\'+@Server+'\RedgateBackup\Prod\'+@DBN+'\'+@DBN+'_'+@Datum+'*.LOG.sqb'''+
' WITH RECOVERY,'+
' REPLACE,'+
' DISCONNECT_EXISTING,'+
' STOPAT = '''+@Datum+' '+@Tijd+''' "'
EXECUTE master..sqlbackup @CMD, @exitcode OUT, @sqlerrorcode OUT


SQL Backup v6.4.0.56
Restoring PROD_00033486 (database) from:
\\rlz-filer1\RLZ-DB11\RedgateBackup\Prod\PROD_00033486\Prod_00033486_20101130_032004.FULL.sqb

Processed 4824 pages for database 'PROD_00033486', file 'QXLAdmin_dat' on file 1.
Processed 1 pages for database 'PROD_00033486', file 'QXLAdmin_log' on file 1.
RESTORE DATABASE successfully processed 4825 pages in 0.207 seconds (182.102 MB/sec).
SQL Backup process ended.



(9 row(s) affected)

name value
exitcode 0
sqlerrorcode 0
filename001 \\rlz-filer1\RLZ-DB11\RedgateBackup\Prod\PROD_00033486\Prod_00033486_20101130_032004.FULL.sqb

(3 row(s) affected)

SQL Backup v6.4.0.56
Restoring PROD_00033486 (transaction logs) from:
\\rlz-filer1\RLZ-DB11\RedgateBackup\Prod\PROD_00033486\Prod_00033486_20101130_032007.LOG.sqb

Processed 0 pages for database 'PROD_00033486', file 'QXLAdmin_dat' on file 1.
Processed 2 pages for database 'PROD_00033486', file 'QXLAdmin_log' on file 1.
This backup set contains records that were logged before the designated point in time. The database is being left in the restoring state so that more roll forward can be performed.
RESTORE LOG successfully processed 2 pages in 0.008 seconds (1.464 MB/sec).

Restoring PROD_00033486 (transaction logs) from:
\\rlz-filer1\RLZ-DB11\RedgateBackup\Prod\PROD_00033486\Prod_00033486_20101130_071418.LOG.sqb

Processed 0 pages for database 'PROD_00033486', file 'QXLAdmin_dat' on file 1.
Processed 2 pages for database 'PROD_00033486', file 'QXLAdmin_log' on file 1.
This backup set contains records that were logged before the designated point in time. The database is being left in the restoring state so that more roll forward can be performed.
RESTORE LOG successfully processed 2 pages in 0.006 seconds (1.790 MB/sec).

Restoring PROD_00033486 (transaction logs) from:
\\rlz-filer1\RLZ-DB11\RedgateBackup\Prod\PROD_00033486\Prod_00033486_20101130_080708.LOG.sqb

Processed 0 pages for database 'PROD_00033486', file 'QXLAdmin_dat' on file 1.
Processed 84 pages for database 'PROD_00033486', file 'QXLAdmin_log' on file 1.
RESTORE LOG successfully processed 84 pages in 0.007 seconds (93.680 MB/sec).

Restoring PROD_00033486 (transaction logs) from:
\\rlz-filer1\RLZ-DB11\RedgateBackup\Prod\PROD_00033486\Prod_00033486_20101130_090203.LOG.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.)

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 12423000000045000001, which is too recent to apply to the database. An earlier log backup that includes LSN 12422000000036700045 can be restored.

SQL Backup exit code: 790
SQL error code: 4305

(43 row(s) affected)

name value
exitcode 790
sqlerrorcode 4305
filename001 \\rlz-filer1\RLZ-DB11\RedgateBackup\Prod\PROD_00033486\Prod_00033486_20101130_032007.LOG.sqb
filename002 \\rlz-filer1\RLZ-DB11\RedgateBackup\Prod\PROD_00033486\Prod_00033486_20101130_071418.LOG.sqb
filename003 \\rlz-filer1\RLZ-DB11\RedgateBackup\Prod\PROD_00033486\Prod_00033486_20101130_080708.LOG.sqb

(5 row(s) affected)


Regards, Nick
· Share on Twitter

Comments

  • peteypetey Posts: 2,358 New member
    Assuming the last few digits in the file names represent the time, it looks like SQL Backup successfully restored the trx logs created at 3:20 AM, 7:14 AM and 8:07 AM. It then tried to restore the trx log created at 9:02 AM, but failed because there's apparently another trx log that was created between 8:07 AM and 9:02 AM.

    You could query the backup history tables on the server instance where the backups were created to check if this is the case e.g.
    SELECT a.backup_start_date, b.physical_device_name, a.*, b.* 
FROM msdb..backupset a 
INNER JOIN msdb..backupmediafamily b ON a.media_set_id = b.media_set_id
WHERE a.database_name = 'PROD_00033486' AND a.type = 'L' AND a.backup_start_date > '30-Nov-2010'
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • NicolasNicolas Posts: 10
    Thanks for looking into it Petey,
    Your query of just the backupset returns the following (ordered by start date):

    backup_start_date backup_set_id
    2010-11-30 03:20:07.000 1838861
    2010-11-30 07:14:19.000 1842905
    2010-11-30 08:07:09.000 1843890
    2010-11-30 09:02:04.000 1843943
    2010-11-30 10:03:51.000 1844058
    2010-11-30 11:03:50.000 1844186
    2010-11-30 12:04:11.000 1844331
    2010-11-30 12:37:56.000 1844368
    2010-11-30 12:40:30.000 1844369
    2010-11-30 13:06:16.000 1844558
    2010-11-30 14:06:06.000 1844816
    2010-11-30 15:03:53.000 1844981
    2010-11-30 16:03:40.000 1845113

    as you can see there is no other log created between 8:07 and 9:02. In fact why should that even matter given that the designated point in time for the restore is 8am? (see the STOPAT directive in the code, which uses the @tijd variable). The filenames that the RESTORE lists at the end would seem to be correct to me: for 8am it would need the 032007, the 071418, and finally the 080708 logs.

    To me it seems a multi-threading issue. There seem to be 4 threads involved in restoring the 090203 log. (Which it shouldn't even be restoring at all).

    Your query with the join to backupmediafamily quadruples the resultset, with family_sequence_number 1, 2, 3 and 4 for each backupset. Would you like me to post those entire results here?

    Regards, Nick
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    My apologies, I didn't notice the STOPAT value, and the fact that you wanted to restore the trx logs up to 8 AM.

    In that case, the error message is expected. SQL Backup uses the STOPAT value for all the trx logs that it restore. It does not automatically stop at the first trx log backup that was created after the STOPAT time. Thus, it'll just continue restoring all trx log backups that it finds, resulting in the error message, which occurs because the 8:07 AM log was not fully restored, hence the 9:07 trx log cannot be restored.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • NicolasNicolas Posts: 10
    Ah, that explains it then. Thanks for the info.
    Except: I'm now not 100% sure, but I think the WITH RECOVERY options will then fail, leaving the database in recovery mode. And that makes the shorthand notation of RESTORE LOG WITH RECOVERY STOPAT *.LOG.sqb (with a wildcard) unusable whenever there is a LOG later than the STOPAT present.

    That is a great pity for us, as we would now be forced to write complex routines that need to determine the exact fileset of logs needed for the STOPAT.

    Regards, Nick
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    Yes, the idea was that the user will provide only the required files to restore to the STOPAT time.

    If you need to automate this, one way may be to check for SQL error code 4305, then run

    RESTORE DATABASE xxx WITH RECOVERY

    after the SQL Backup job step. The disadvantage of this is that error code 4305 may actually have been raised because a backup set was missing, and not because the last restored trx log was partially restored.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • NicolasNicolas Posts: 10
    Great, that'll do fine as a work-around.

    Thanks,
    Nick
    · Share on Twitter
Sign In or Register to comment.