MS SQL 2008 R2 Restore database using STOPATMARK applys all log transactions (does not stop at LSN or transaction MARK)

Question

Hello there;

1- Took a full back as follow:

       BACKUP DATABASE [NetFlow] TO  [NetFlow_DataFile_Bkups] WITH  RETAINDAYS = 5, NOFORMAT, NOINIT,  
       NAME = N'NetFlow-Full Database Backup', SKIP, NOREWIND, NOUNLOAD,  STATS = 10
       GO

2- Issued an update sql:

       Use NetFlow
       go   
       Begin transaction Updateipv0
        with mark 'UpdateTestcol'
       go
       update [NetFlow].[msafiari].[ipv0] set testcol = 2222 where ipAddress =  '22.135.210.62'
       go
       commit transaction Updateipv0
       go

3- Took a log backup as follow:

       BACKUP LOG [NetFlow] TO  [NetFlow_Log_Bkups] WITH  RETAINDAYS = 5, NOFORMAT, NOINIT,  
       NAME = N'NetFlow-Transaction Log  Backup', SKIP, NOREWIND, NOUNLOAD,  STATS = 10
       GO

4- Issued another update sql:

       update [NetFlow].[msafiari].[ipv0] set testcol = 3333 where ipAddress =  '80.53.158.6'

5- Took a tail end log backup:

       BACKUP LOG [NetFlow] TO  [NetFlow_Log_Bkups] WITH  NO_TRUNCATE ,  RETAINDAYS = 5, NOFORMAT, NOINIT,  
       NAME = N'NetFlow-Transaction Log  Backup', SKIP, NOREWIND, NOUNLOAD,  NORECOVERY ,  STATS = 10
       GO

6- Then restored full baclup:

       RESTORE DATABASE [NetFlow] FROM  DISK = N'D:\NetFlow_DataFile_Bkups\DataFile_Backups' WITH  FILE = 2,  
       NORECOVERY,  NOUNLOAD,  STATS = 10
       GO

7- Restored First log backup:

       RESTORE LOG [NetFlow] FROM  DISK = N'D:\NetFlow_Log_Bkups\Log_Backups' WITH  FILE = 10, NOUNLOAD,  
       RECOVERY, STOPATMARK = 'UpdateTestcol'; STATS = 10
       GO

    I received: This log file contains records logged before the designated mark.

                 The database is being left in the Restoring state so you can apply another log file.

    Note: RECOVERY option was ignored     <===========

8- Then I restored the last log backup (tail end):

       RESTORE LOG [NetFlow] FROM  DISK = N'D:\NetFlow_Log_Bkups\Log_Backups' WITH  FILE = 11,  NOUNLOAD,  
       RECOVERY, STOPATMARK = 'UpdateTestcol', STATS = 10;
       GO

     I received: This log file contains records logged before the designated mark.
                  The database is being left in the Restoring state so you can apply another log file. 

    NOTE: RECOVER option was ignored again, So I had to issue:    <==============

               RESTORE DATABASE netflow with RECOVERY

    to bring database to ready to use mode.

9- At this point I issued a SELECT query against the table (ipv0) and I see the last update statment in effect,

    (means testcol = 3333)

I have to mention that I practiced to do recovery using STOPATMARK pointing to LSN

(STOPATMARK = '0x000001590000009F0004') and I got the same result. The only way that I can recover to point in time is using STOPAT with date and time.

Thanks,

Moe.

Answer 1

Moe,

I'm not sure why the recovery option didn't take, but I would attribute it to the incorrect value in the STOPATMARK option (but I didn't test using an incorrect mark name) making SQL Server not see the mark name in the log and continuing to ask for more logs. When using WITH MARK, the transaction needs to be named as you have above Updateipv0. When you specify a value after MARK using your example:

Begin transaction Updateipv0 with mark 'UpdateTestcol'

The transaction is named Updateipv0 and the DESCRIPTION is UpdateTestCol. This can be verified by running the following:

SELECT * FROM msdb.dbo.logmarkhistory

Also refer:

http://msdn.microsoft.com/en-us/library/ms188623.aspx

http://msdn.microsoft.com/en-us/library/ms187014.aspx

Try running your sample again, but using the mark name and not the description to see if it works.

-Sean

Answer 2

Hi Sean;

I did repeat the same process (step 1 to 9) and pointed to correct MARK name ("Update1" and not MARK Description) but result was the same.

Following from

SELECT * FROM msdb.dbo.logmarkhistory


database_name    mark_name    description                       user_name   lsn                                   mark_time   
---------------------------------------------------------------------------------------------------------------------------------------------------
NetFlow                Updateipv0     UpdateTestcol                  CA                357000000029700005    2012-03-16 09:28:47.383
NetFlow                Update1          change testcol to 3333    CA                511000000756300005    2012-04-12 13:09:00.283

This time I picked up Update1.

Following from restore process:

RESTORE DATABASE [NetFlow] FROM  DISK = N'D:\NetFlow_DataFile_Bkups\DataFile_Backups' WITH  FILE = 3,  
NORECOVERY,  NOUNLOAD,  STATS = 10
GO

RESTORE LOG [NetFlow] FROM  DISK = N'D:\NetFlow_Log_Bkups\Log_Backups' WITH  FILE = 13,  
RECOVERY, STOPATMARK = 'Update1',  NOUNLOAD,  STATS = 10
GO

10 percent processed.
21 percent processed.
32 percent processed.
43 percent processed.
50 percent processed.
61 percent processed.
71 percent processed.
82 percent processed.
93 percent processed.
100 percent processed.
Processed 3560 pages for database 'NetFlow', file 'NetFlow' on file 3.
Processed 3 pages for database 'NetFlow', file 'NetFlow_log' on file 3.
RESTORE DATABASE successfully processed 3563 pages in 1.502 seconds (18.528 MB/sec).
10 percent processed.
20 percent processed.
30 percent processed.
40 percent processed.
50 percent processed.
60 percent processed.
70 percent processed.
80 percent processed.
90 percent processed.
100 percent processed.
Processed 0 pages for database 'NetFlow', file 'NetFlow' on file 13.
Processed 30021 pages for database 'NetFlow', file 'NetFlow_log' on file 13.
This log file contains records logged before the designated mark. The database is being left in the Restoring state so you can apply another log file.
RESTORE LOG successfully processed 30021 pages in 4.082 seconds (57.455 MB/sec).

           Please Note:  RECOVERY option is ignored and database is in restore pending mode.

So I restored tail log:

RESTORE LOG [NetFlow] FROM  DISK = N'D:\NetFlow_Log_Bkups\Log_Backups' WITH  FILE = 14,  
RECOVERY, STOPATMARK = 'Update1', NOUNLOAD,  STATS = 10
GO

100 percent processed.
Processed 0 pages for database 'NetFlow', file 'NetFlow' on file 14.
Processed 3 pages for database 'NetFlow', file 'NetFlow_log' on file 14.
This log file contains records logged before the designated mark. The database is being left in the Restoring state so you can apply another log file.
RESTORE LOG successfully processed 3 pages in 0.199 seconds (0.090 MB/sec).

            Please Note:  RECOVERY option is ignored againg and still database is in restore pending mode, so I had to issue:

RESTORE DATABASE netflow with RECOVERY

RESTORE DATABASE successfully processed 0 pages in 4.661 seconds (0.000 MB/sec).

But here when I suue "SELECT [ipAddress] ,[testcol]  FROM [NetFlow].[msafiari].[ipv0]" I see all of my updateds.

As I mentioned before I practiced to do recovery using STOPATMARK pointing to LSN

(STOPATMARK = '0x000001590000009F0004') and I got the same result. The only way that I can recover to point in time is using STOPAT with date and time, so it means if customer does not  know the time to recover but does know the LSN from CDC the recovery function would not work.

To resolve this issue I am willing to get into more deep diagnostic technique if possible.

Sorry that it took sometime to update this case, I promise to check this case everyday.

Thnaks,

-Moe.

Answer 3

Moe,

I believe you aren't using the correct files in your restore, please check the lsn values of the log files against the lsn record in the history table. I had no issues making a quick demo:

CREATE DATABASE STOPAT_Test;
GO

USE STOPAT_Test;
GO

ALTER DATABASE STOPAT_Test SET Recovery FULL
GO

CREATE TABLE MyData
(
ID			INT IDENTITY(1,1),
DataValue	VARCHAR(50) NOT NULL
);
GO

INSERT INTO MyData(DataValue) VALUES ('The First Entry');

BACKUP DATABASE [STOPAT_Test] TO DISK = N'C:\backup\STOPAT_Test_Full.bak' WITH CHECKSUM, INIT, STATS=10

BEGIN TRAN MyTran1 WITH MARK 'Tran1'
INSERT INTO MyData(DataValue) VALUES ('The Second Entry');
COMMIT TRAN MyTran1

BACKUP LOG [STOPAT_Test] TO DISK = N'C:\backup\STOPAT_Test_Log_1.trn' WITH CHECKSUM, INIT, STATS=10

INSERT INTO MyData(DataValue) VALUES ('The Third Entry');

BEGIN TRAN MyTran2 WITH MARK 'Tran2'
INSERT INTO MyData(DataValue) VALUES ('The Fourth Entry');
COMMIT TRAN MyTran2

BACKUP LOG [STOPAT_Test] TO DISK = N'C:\backup\STOPAT_Test_Log_2.trn' WITH CHECKSUM, INIT, STATS=10

INSERT INTO MyData(DataValue) VALUES ('The Fifth Entry');

BACKUP LOG [STOPAT_Test] TO DISK = N'C:\backup\STOPAT_Test_Log_3.trn' WITH CHECKSUM, INIT, NO_TRUNCATE, STATS=10


/* check data */
SELECT * FROM dbo.MyData

/* start restore process */
ALTER DATABASE [STOPAT_Test] SET SINGLE_USER WITH ROLLBACK IMMEDIATE
GO
USE master
GO

RESTORE DATABASE [STOPAT_Test] FROM DISK = N'C:\backup\STOPAT_Test_Full.bak' WITH REPLACE, NORECOVERY, STATS=10

RESTORE LOG [STOPAT_Test] FROM DISK = N'C:\backup\STOPAT_Test_Log_1.trn' WITH STOPBEFOREMARK = 'MyTran1', STANDBY = N'C:\backup\stndby.sbf', STATS=10

USE STOPAT_Test
GO

/* only data from before the transaction is there STOPBEFOREMARK */
SELECT * FROM dbo.MyData


USE MASTER
GO

RESTORE LOG [STOPAT_Test] FROM DISK = N'C:\backup\STOPAT_Test_Log_1.trn' WITH STOPATMARK = 'MyTran1', STANDBY = N'C:\backup\stndby.sbf', STATS=10

USE STOPAT_Test
GO
/* we stopped AT the mark now, so we have the data */
SELECT * FROM dbo.MyData

USE MASTER
GO

/* finish any transaction from the end of Log_1.trn and stop BEFORE MyTran2 */
RESTORE LOG [STOPAT_Test] FROM DISK = N'C:\backup\STOPAT_Test_Log_1.trn' WITH STANDBY = N'C:\backup\stndby.sbf', STATS=10
RESTORE LOG [STOPAT_Test] FROM DISK = N'C:\backup\STOPAT_Test_Log_2.trn' WITH STOPBEFOREMARK = 'MyTran2', RECOVERY, STATS=10
GO

USE STOPAT_Test
GO

/* everything before MyTran 2 */
SELECT * FROM dbo.MyData

ALTER DATABASE STOPAT_Test SET SINGLE_USER WITH ROLLBACK IMMEDIATE
GO


USE master
GO
DROP DATABASE [STOPAT_Test]

-Sean

Answer 4

 Sean;

Thank you very much for your quick demo, may be the problem I was having was related to log tail end back-up, I have noticed that you did not take a tail end back-up from log.

Any how I deleted all backup files and history then followed the steps that you have provided, everything worked fine.

I have noticed your comment:

/* finish any transaction from the end of Log_1.trn and stop BEFORE MyTran2 */

I modified it as:

/* Following is going to apply all transactions from the begining of MyTran1 and stop BEFORE MyTran2 */

Thanks again.

Regards;

-Moe.

Answer 5

Moe,

Tail of the log backup shouldn't change anything as it occurs after the transaction has already been committed or rolled back.

-Sean

Answer 6

Hi Sean;

The reason that I brought up tail end log back-up is that my last log back-up put database in restring mode
(because of NORECOVERY option) but yours does not. I was thinking that may be database engine would like to
restore it back to the tail end that put database in restoring mode.

Thanks,

-Moe.