An adventure on SQL Server performance and features

SQL Server: How to Find a safe restore point (and who messed up) by reading from the Transaction Log

S

Panic: Someone has messed up and deleted a super important piece of information in a table!
Who did it? Nobody knows.
When did it happen? “The data was there this morning”
Super useful info, thanks brah.

So you activate your DBA Magic Powers© and try to deal with this stuff yourself: you need to identify which is the exact point where the data has been deleted (in order to minimize data loss) and eventually who did it (to have someone to blame, instruct on query best practices or blackmail, your choice).

So, how? If your DB was in Full recovery model, we can use the active part of the transaction log to identify which were the latest delete operations on the DB; If the DB was in Simple Recovery model the point-in-time restore isn’t even an option so why the hell are you reading this? Just restore the latest FULL/DIFF backup and get the data from there  ¯\_(ツ)_/¯

Let’s set up a very simple example:

CREATE TABLE TestTable 
( ID int identity primary key clustered,
  Number int DEFAULT 0
 );
 GO

 INSERT INTO TestTable
 DEFAULT VALUES

 GO 10

So, I have a table with 10 useless records. Then, let’s say that a user with the intention to be blackmailed deletes half of the stuff in the table because he messed up, I’ll simulate it by creating a new user and running the delete statement as him:

CREATE USER [BlackmailMe] WITHOUT LOGIN WITH DEFAULT_SCHEMA=[dbo]
GO

 EXECUTE AS USER = 'BlackmailME';

 DELETE FROM TestTable
 WHERE ID % 2 = 0

 GO

Then someone comes up running telling you the things we said in the 1st paragraph, how do we proceed?
I wrote this script only for you:

--Reads the active transaction log looking for user actions

WITH UserTransactions
     AS (
     SELECT
            [USR].[name],
            LOG.[Transaction ID],
            [Transaction Name],
            [Begin Time],
            [End Time]
     FROM   [sys].[fn_dblog](NULL, NULL) LOG
            JOIN [sysusers] [USR] ON [USR].[sid] = LOG.[Transaction SID])
     SELECT
            [UT].[name] AS [UserName],
            [SCH].[name] AS [SchemaName],
            [OBJ].[name] AS [Objectname],
            LOG.[Transaction ID],
            [UT].[Transaction Name],
            COALESCE(LOG.[Begin Time], LOG.[End Time]) AS Time,
            LOG.[Operation],
            LOG.[Context],
            [Current LSN],
            [Lock Information]
     FROM   [UserTransactions] [UT]
            JOIN [sys].[fn_dblog](NULL, NULL) LOG ON LOG.[Transaction ID] = [UT].[Transaction ID]
            LEFT JOIN [sys].[partitions] [PART] ON [PART].[partition_id] = LOG.[PartitionId]
            LEFT JOIN [sys].[objects] [OBJ] ON [OBJ].object_id = [PART].object_id
            LEFT JOIN [sys].[schemas] [SCH] ON [SCH].schema_id = [OBJ].schema_id
     WHERE  [SCH].[name] IS NOT NULL  --Comment this predicate to show statements related to dropped objects
            AND [SCH].[name] <> 'sys' --Comment this predicate to show statements that write to system tables (e.g CREATE TABLE)
     ORDER BY
              LOG.[Current LSN] DESC;

This uses the undocumented but very cool and dangerous (for SQL 2014 and down, depending on the SP/CU installed ) sys.fn_dblog DMF that reads from the active part of the transaction log and gives you tens of columns of more or less useful information; By joining it around with the sysusers table and some other DMV as Objects, Schemas and Partitions we can come up with this kind of output:

As you can see in the output we have the Blackmail guy that executed the delete statement, we don’t have an actual time in the classic sense but we have what matters most, the LSN of the operation.
BUT WAIT, THERE IS MORE!
Really, there is a little bit more to do as the LSN shown in the log isn’t in the same format as you would actually use during the restore process.
I’ve used this article by Robert L Davis (aka SQLSoldier) as a reference to enhance my script, you can check out the logic there, it’s explained better than I ever could.
[Robert was a great guy, I loved his blog posts, and unfortunately recently passed away (more here)]

This brings us to a shiny new version of the original script:

--Reads the active transaction log looking for user actions

WITH UserTransactions
     AS (
     SELECT
            [USR].[name],
            LOG.[Transaction ID],
            [Transaction Name],
            [Begin Time],
            [End Time],
            [Current LSN]
     FROM   [sys].[fn_dblog](NULL, NULL) LOG
            JOIN [sysusers] [USR] ON [USR].[sid] = LOG.[Transaction SID])
     SELECT
            [UT].[name] AS [UserName],
            [SCH].[name] AS [SchemaName],
            [OBJ].[name] AS [Objectname],
            LOG.[Transaction ID],
            [UT].[Transaction Name],
            COALESCE(LOG.[Begin Time], LOG.[End Time]) AS Time,
            LOG.[Operation],
            LOG.[Context],
            LOG.[Current LSN],
            [DECODE].[Current LSN(Decoded)],
            [Lock Information]
     FROM      [UserTransactions] [UT]
               JOIN [sys].[fn_dblog](NULL, NULL) LOG ON LOG.[Transaction ID] = [UT].[Transaction ID]
               LEFT JOIN [sys].[partitions] [PART] ON [PART].[partition_id] = LOG.[PartitionId]
               LEFT JOIN [sys].[objects] [OBJ] ON [OBJ].object_id = [PART].object_id
               LEFT JOIN [sys].[schemas] [SCH] ON [SCH].schema_id = [OBJ].schema_id
               CROSS APPLY
(
    SELECT
           CAST(CAST(CONVERT(VARBINARY, '0x'+RIGHT(REPLICATE('0', 8)+LEFT([U].[Current LSN], 8), 8), 1) AS INT) AS VARCHAR(8))+CAST(RIGHT(REPLICATE('0', 10)+CAST(CAST(CONVERT(VARBINARY, '0x'+RIGHT(REPLICATE('0', 8)+SUBSTRING([U].[Current LSN], 10, 8), 8), 1) AS INT) AS VARCHAR(10)), 10) AS VARCHAR(10))+CAST(RIGHT(REPLICATE('0', 5)+CAST(CAST(CONVERT(VARBINARY, '0x'+RIGHT(REPLICATE('0', 8)+RIGHT([U].[Current LSN], 4), 8), 1) AS INT) AS VARCHAR(5)), 5) AS VARCHAR(5)) AS [Current LSN(Decoded)]
    FROM   [UserTransactions] [U]
    WHERE  [U].[Current LSN] = [UT].[Current LSN]
) AS [DECODE]
     WHERE [SCH].[name] IS NOT NULL  --Comment this predicate to show statements related to dropped objects
           AND [SCH].[name] <> 'sys' --Comment this predicate to show statements that write to system tables (e.g CREATE TABLE)
     ORDER BY
              LOG.[Current LSN] DESC;

Robert’s logic is applied in the CROSS APPLY syntax, of course.
In the output you’ll see that I now have a column with the decoded (and usable) LSN code:

NOW you can really use that LSN to restore to the point in time exactly before that delete happened; restoring the the database to just before that point is as easy as:

  • Backup the active transaction log
  • Restore the Full DB backup
  • Restore the latest (eventual) Diff Backup
  • Restore any Transaction Log backups prior to the latest one
  • Restore the latest one with this syntax:
RESTORE LOG TestDatabase FROM DISK = 'C:\Temp\TestDatabase_last_log.bak'   
WITH STOPBEFOREMARK = 'lsn:35000000088900008'  
GO

And that’s about it!
You can even apply this logic to “older” transactions that are no more present in the active transaction log (because it was already backed up), in that case you can switch up the use of the fn_dblog  with fn_dump_dblog in order to read from aLog backup as opposed from the existing log.

About the author

Emanuele Meazzo

Add comment

An adventure on SQL Server performance and features

Emanuele Meazzo

My Social Profiles

If you're interested in following me around in the social world, here are some URLs for you