Read the SQL Server Database Transaction Log

Read the SQL Server Database Transaction Log

Who deleted that data?! Or worse -- who dropped that table?!  It really frustrates me when something like this occurs on the servers that I am responsible for... yet I am unaware.  Here is a quick piece to show you that yes, we can read the database transaction log, and we can figure out who made that unauthorized change.

 

First we need to create a test table.

   -- create test table

   CREATE TABLE [Personnel] (

      [UserID] INT IDENTITY(1,1),

      [UserName] VARCHAR(55),

      [Dept] CHAR (25)

    );

 

--Ok. Now let us look in the log file to see that new table.

 

   -- look in log for that table creation

   SELECT 

      [Current LSN],

      [Operation],

      [Transaction Name],

      [SPID],

      [Begin Time]

    FROM   

      fn_dblog(NULL,NULL)

   WHERE  

     [Transaction Name] = 'CREATE TABLE'

 

--Current LSN Operation Transaction Name SPID BeginTime

--00000020:00000f70:002c LOP_BEGIN_XACT CREATE TABLE 64 2014/02/05 12:10:41:093

--Sweet!  Now let us write something into the table.

   -- write into test table

   INSERT dbo.Personnel (UserName,Dept)

    SELECT 'John Doe','Accounting'

   UNION

   SELECT 'Jane Doe','Mangement'

 

 --Look at our data:

 

   SELECT * FROM dbo.Personnel

 

--Ok. Now we are going to do that unauthorized DELETE. 

   /* delete something */

   DELETE dbo.Personnel

    WHERE UserName = 'Jane Doe'

 

--Check the log... it is there.

 

   -- read the log

   SELECT 

       [Transaction ID],

       [Operation],

       [Context],

       [AllocUnitName]

    FROM   

       fn_dblog(NULL,NULL)

   WHERE   

      Operation = 'LOP_DELETE_ROWS'

       AND AllocUnitName = 'dbo.Personnel'

 

Transaction ID	Operation	Context	AllocUnitName
0000:00000557	LOP_DELETE_ROWS	LCX_HEAP	dbo.Personnel

Now, we need to use that Transaction ID returned above to get the Transaction SID. 
This will help us find the actual user who performed this action.

   -- get the transaction sid
   SELECT 
       [Transaction ID],
       [Transaction SID],   
      [Operation],
       [AllocUnitName]
    FROM   
       fn_dblog(NULL,NULL)
   WHERE    
      [Transaction ID] = '0000:00000550'
 
 

Transaction ID	Transaction SID	Operation	AllocUnitName
0000:00000557	0x010500000000000515000000EFEE1C9FBC493493D723D1D8E8030000	LOP_DELETE_ROWS	dbo.Personnel

Ok. This is the gold! Now we use the Transaction SID to figure out who actually performed the delete!

   -- find the offending user
   USE master;
    SELECT SUSER_SNAME(0x010500000000000515000000EFEE1C9FBC493493D723D1D8E8030000) [Login]
 

Login

MyMachine\MyName

Alright. One better. Let us drop that Personnel table.
 
   -- drop table
   DROP TABLE dbo.Personnel
 
Just like before, let us get our Transaction ID, and then our Transaction SID.
 
   -- get transaction id
   SELECT
       [Transaction ID],
       [Transaction SID],
       [Transaction Name], 
      [Operation],
       [Description]
    FROM  
       fn_dblog(NULL,NULL)
   WHERE
      [Transaction Name] = 'DROPOBJ'
 
And now... we find the guy who dropped the table.
 

   -- pass transaction sid to get user name
   USE master;
    SELECT SUSER_SNAME(0x010500000000000515000000EFEE1C9FBC493493D723D1D8E8030000) [Login]
 

It is undocumented, so you need to be cautious.  But, it is very easy method for reading into your transaction log files.

Reading the SQL Server log files - Part2
How to read the SQL Server Database Transaction Log

I will explain how to read your database transaction log file and how transactions are written for your database if you perform any database activity. This tip is helpful if you want to know what the transaction log file captures. There is an undocumented function called "fn_dblog" which enables you to read data from your transaction log which contains very informative data about things that are happening in your database. I strongly suggest testing any undocumented features in a lab environment first.
The function (fn_dblog) requires a beginning LSN and ending LSN for a transaction.  NULL is the default for this function and this will return all log records from the transaction log file.

Create a Test Database

To show how this works, we will create a database and a table to play with this function. Run the below SQL code to create a database and table.

--Create DB.
USE [master];
GO
CREATE DATABASE ReadingDBLog;
GO
-- Create tables.
USE ReadingDBLog;
GO
CREATE TABLE [Location] (
    [Sr.No] INT IDENTITY,
    [Date] DATETIME DEFAULT GETDATE (),
    [City] CHAR (25) DEFAULT 'Bangalore');

We have created a database named "ReadingDBLog" and a table 'Location' with three columns. Now you can check all information and processes which have been used by SQL Server to create the database and table. We will run the below code to check the log file for this newly created database to check what processes and steps SQL Server took to create the database and table.

USE ReadingDBLog;
GO
select COUNT(*) from fn_dblog(null,null)

We can see there are 339 rows that have been generated for just creating a dummy database and a blank table. You can go and check the logs by using this function to get details for all processes used to create the database and table. Look at the below code to see the data in the transaction log file.

USE ReadingDBLog;
GO
select [Current LSN],
       [Operation],
       [Transaction Name],
       [Transaction ID],
       [Transaction SID],
       [SPID],
       [Begin Time]
FROM   fn_dblog(null,null)

As the total number of rows and columns are large, I gave a snapshot of some of the columns and rows but I have tried to capture a few informative columns here. You can see in the above screenshot that the transaction name column shows the database name, similarly it will show the create table for the table creation code. Transaction ID is the same for all parts of a transaction. The value for transaction name will be filled only when the particular transaction starts with "LOP_BEGIN_XACT" in the Operation column. "LOP_BEGIN_XACT" means begin transaction. The operation column will let us know which operation is performing like an insert, update, delete, shrink, lock, page allocation etc...  It is pretty easy to understand the operation based on these key words to see what operation is being performed by SQL Server.

Run some DML commands to see what is captured

Now we will run a few DML scripts to check how data insertion, updating or deletion is logged in the database log file. During this operation you can also track how a page is allocated or de-allocated.

USE ReadingDBLog
go
INSERT INTO Location DEFAULT VALUES ;
GO 100
GO
UPDATE Location
SET City='New Delhi'
WHERE [Sr.No]<5
GO
DELETE Location 
WHERE [Sr.No]>90
Go

Let's check our database log file again. As we saw from above, there is a lot of info logged in the transaction log file, so I will filter the data.

USE ReadingDBLog
go
SELECT
 [Current LSN],
 [Transaction ID],
 [Operation],
  [Transaction Name],
 [CONTEXT],
 [AllocUnitName],
 [Page ID],
 [Slot ID],
 [Begin Time],
 [End Time],
 [Number of Locks],
 [Lock Information]
FROM sys.fn_dblog(NULL,NULL)
WHERE Operation IN 
   ('LOP_INSERT_ROWS','LOP_MODIFY_ROW',
    'LOP_DELETE_ROWS','LOP_BEGIN_XACT','LOP_COMMIT_XACT')  

Your output will look something like the above screenshot after running the above script.
Let's see how we can read the output. You can see the highlighted area which we will read as:

• INSERT statement with transaction ID 0000:00000448
• started at 2013/09/27 16:50:44:530
• INSERTed a row in a HEAP table 'dbo.Location' in pageID 0001:00000099
• finished at 2013/09/27 16:50:44:530

 Similarly, it will show you this same kind of information for UPDATE and DELETE statements.

Finding internal SQL Server operations in transaction log

We can also check internal functions of SQL Server through this function. Let's take for example page splitting. We can track all info about page splits like how many times page splits occur, on which page and during which operation. Let's take a look at this below to see page splits for the above INSERT operation. Run the below SQL code to get all operations related to page splits.

USE ReadingDBLog
go
--Get how many times page split occurs.
SELECT 
 [Current LSN],
 [Transaction ID],
 [Operation],
  [Transaction Name],
 [CONTEXT],
 [AllocUnitName],
 [Page ID],
 [Slot ID],
 [Begin Time],
 [End Time],
 [Number of Locks],
 [Lock Information]
FROM sys.fn_dblog(NULL,NULL)
WHERE [Transaction Name]='SplitPage' 
GO

--Get what all steps SQL Server performs during a single Page Split occurrence.
SELECT 
 [Current LSN],
 [Transaction ID],
 [Operation],
  [Transaction Name],
 [CONTEXT],
 [AllocUnitName],
 [Page ID],
 [Slot ID],
 [Begin Time],
 [End Time],
 [Number of Locks],
 [Lock Information]
FROM sys.fn_dblog(NULL,NULL)
WHERE [Transaction ID]='0000:00000451'  

As you can see above Page Split occur three times for the above DML activity. The first script will let us know how many times page splits occurred and the second script elaborates on the internal processes SQL Server ran during a single Page Split operation. The above image takes the first page split, transaction ID '0000:00000451', and shows all internal processes in the second result set.
Similarly if you drop any object or you perform other database operations they will get logged in the transaction log file which will then be visible using this function.

How a backup interacts with the transaction log

Now I will run a backup and see the transaction log file again. Run a backup on this database and then again check the transaction log file.

SELECT COUNT(*)
FROM fn_dblog(null,null)
GO

BACKUP DATABASE ReadingDBLog TO DISK = 'c:\ReadingDBLog_Full.bak'
GO

SELECT COUNT(*)
FROM fn_dblog(null,null)
GO

As we can see, the number of rows has been drastically reduced after doing a backup and it has been reduced to 9 rows from 528. This means the inactive part of the log which tracked the transactions has been dumped to a backup file and the original entries from the log file have been flushed. Now you can shrink the log file if necessary.

Other things you can do

You can also use the DBCC Log() command to see log information, but this command will not give you detail information. You can also use trace flag 2537 to look at all logs and not just the active log.