Transaction Tracking Continued

In my last blog, I wrote about the use of fn_dblog that helped us in querying the log to find the exact information with respect to a transaction that we needed to track down. Let us look at the scenario that we are going to tackle today:

Someone dropped a table and we want to find out when it happened and  maybe who did it. The default trace has wrapped meaning it has been overwritten so we can’t get the DDL trace from there anymore.

If the transaction log for the DROP hasn’t yet been cleared from the active portion of the log when we’d be able to use fn_dblog to search through the log fro the information we need as per my last blog. We might even be able to look in the inactive portion of the log by using trace flag 2536, which instructs the log reader to ignore the log truncation point and dump all possible log records from the log.

But what do we do if the pertinent log records just don’t exist in the log anymore? They’re only in our log backups. We could tediously find our way through restoring the of backups a few seconds at a time until we find the point at which the DROP took place, and then restore to just before that point so we can get the data back.

Or we could save a whole ton of time and use fn_dump_dblog which allows us to dump and search log records from a log backup file, without having the restore the database.

Note: The function fn_dump_dblog creates a new hidden SQLOS scheduler and up to three threads, which will not go away and will not be reused until a server restart. It’s a bug which has been fixed in SQL Server 2012 SP2 and above and SQL Server 2014 going forward. The fix has not been backported any earlier and so it is advised not to be used in prior versions

Ok then let’s see an example – We are going to create a table, populate it, back it up, then drop it.

USE[master];
GO
CREATEDATABASE[FNDBLogTest];
GO
USE[FNDBLogTest];
GO
SETNOCOUNTON;
GO
-- Create tables to play with
CREATETABLE[ProdTable](
    [c1]INTIDENTITY,
    [c2]DATETIMEDEFAULTGETDATE(),
    [c3]CHAR(25)DEFAULT'a');
CREATETABLE[ProdTable2](
    [c1]INTIDENTITY,
    [c2]DATETIMEDEFAULTGETDATE(),
    [c3]CHAR(25)DEFAULT'a');
GO
INSERTINTO[ProdTable]DEFAULTVALUES;
GO1000
-- Take initial backups
BACKUPDATABASE[FNDBLogTest]TODISK=N'D:\SQL2012\FNDBLogTest_Full.bak'WITHINIT;
GO
BACKUPLOG[FNDBLogTest]TODISK=N'D:\SQL2012\FNDBLogTest_Log1.bak'WITHINIT;
GO
INSERTINTO[ProdTable2]DEFAULTVALUES;
GO1000
Now we’ll drop the table and add some more log records:
DROPTABLE[ProdTable];
GO
INSERTINTO[ProdTable2]DEFAULTVALUES;
GO1000
Now how can we find the point at which the table was dropped?
SELECT
    [Current LSN],
    [Operation],
    [Context],
    [Transaction ID],
    [Description]
FROM
    fn_dblog(NULL,NULL),
    (SELECT
        [Transaction ID]AS[tid]
    FROM
        fn_dblog(NULL,NULL)
    WHERE
        [Transaction Name]LIKE'%DROPOBJ%')[fd]
WHERE
    [Transaction ID]=[fd].[tid];
GO
snap1

That’s awesome

Now we’ll take another log backup, which clears the log, and contains the log we just looked at.

BACKUPLOG[FNDBLogTest]TODISK=N'D:\SQL2012\FNDBLogTest_Log2.bak'WITHINIT;
GO
Who did the DROP?

If we want to figure out who ran the DROP command, look at the Transaction SID field for the DROP transaction’s LOP_BEGIN_XACT log records and the pass that value into the SUSER_SNAME() function. Simple!

Restoring using STOPBEFOREMARK

The LSN for the LOP_BEGIN_XACT log record is where we need to restore to just before. To do that we can just plug in the LSN to the STOPBEFOREMARK option for RESTORE. The option is documented but the format is not. The LSN needs to be specified with ‘0x‘ in front of it, and then the format is exactly as returned by fn_dblog.
The restore sequence to restore to just before the DROP is therefore:
RESTOREDATABASE[FNDBLogTest2]
    FROMDISK=N'D:\SQL2012\FNDBLogTest_Full.bak'
WITH
    MOVEN'FNDBLogTest'TON'C:\SQL2012\FNDBLogTest2.mdf',
    MOVEN'FNDBLogTest_log'TON'C:\SQL2012\FNDBLogTest2_log.ldf',
    REPLACE,NORECOVERY;
GO
RESTORELOG[FNDBLogTest2]
    FROMDISK=N'D:\SQL2012\FNDBLogTest_Log1.bak'
WITH
    NORECOVERY;
GO
RESTORELOG[FNDBLogTest2]
FROM
    DISK=N'D:\SQL2012\FNDBLogTest_Log2.bak'
WITH
    STOPBEFOREMARK ='lsn:0x0000009d:0000021e:0001',
    NORECOVERY;
GO
RESTOREDATABASE[FNDBLogTest2]WITHRECOVERY;
GO
And the table is there again, right before the point it was dropped. We can see where we used the constructed LSN string in the final log restore.
Using fn_dump_dblog
So what if the log records are no longer in the log? We can use the fn_dump_dblog function. For instance, here is how we can use it to look in the FNDBLogTest_Log2.bak backup that we created earlier:
SELECT
    COUNT(*)
FROM
    fn_dump_dblog(
        NULL,NULL,N'DISK',1,N'D:\SQL2012\FNDBLogTest_Log2.bak',
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT);
GO
We have to specify all the DEFAULT parameters, all 63 of them or it just won’t work. The other parameters are:
  • Starting LSN (usually just NULL)
  • Ending LSN (again, usually just NULL)
  • Type of file (DISK or TAPE)
  • Backup number within the backup file (for multi-backup media sets)
  • File name

So we could do the same query as we did above:

SELECT
    [Current LSN],
    [Operation],
    [Context],
    [Transaction ID],
    [Description]
FROM
    fn_dump_dblog(
        NULL,NULL,N'DISK',1,N'D:\SQL2012\FNDBLogTest_Log2.bak',
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT),
    (SELECT
        [Transaction ID]AS[tid]
    FROM
        fn_dump_dblog(
            NULL,NULL,N'DISK',1,N'D:\SQL2012\FNDBLogTest_Log2.bak',
            DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
            DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
            DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
            DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
            DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
            DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
            DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
            DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
            DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT)
    WHERE
        [Transaction Name]LIKE'%DROPOBJ%')[fd]
WHERE[Transaction ID]=[fd].[tid];
GO
Which works perfectly, but takes much longer to run.
So maybe you are wondering what all the other parameters to fn_dump_dblog are for? They are for specifying the media families of a media set that has more than one media family.
Here’s an example using a log backup striped across two files:
BACKUPLOG[FNDBLogTest]TO
    DISK=N'D:\SQL2012\FNDBLogTest_Log3_1.bak',
    DISK=N'D:\SQL2012\FNDBLogTest_Log3_2.bak'
WITHINIT;
GO
If we try to use fn_dump_dblog and only specify a single file, we get an error:

 

SELECT
    COUNT(*)
FROM
    fn_dump_dblog(
        NULL,NULL,N'DISK',1,N'D:\SQL2012\FNDBLogTest_Log3_1.bak',
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT);
GO
Msg 3132, Level 16, State 1, Line 1
The media set has 2 media families but only 1 are provided. All members must be provided.
So we have to specify both media families:
SELECT
    COUNT(*)
FROM
    fn_dump_dblog(
        NULL,NULL,N'DISK',1,N'D:\SQL2012\FNDBLogTest_Log3_1.bak',
        N'D:\SQL2012\FNDBLogTest_Log3_2.bak',DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,
        DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT,DEFAULT);
GO
So there you have it – some more powerful tools to add to your disaster recovery arsenal. Although do note that we do need log data whether it be active/inactive logs or log backups.
Do write your thoughts regarding this two part series blog that I have written regarding transaction tracking as well as point in time restore of logs.
Advertisements
This entry was posted in Best Practices, ms sql, Troubleshooting, Uncategorized and tagged , , , , , , , . Bookmark the permalink.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s