About Contact Us

Finding a transaction in the log for a particular user

By: Paul Randal
Posted on: June 3, 2015 11:45 am

In the last IEHADR class we just had in Chicago, I was doing a demo of looking in the transaction log to find the point at which a table was dropped so a restore could be performed (as described in this blog post). One of the students asked how to find a transaction for a particular user, so I demo’d that and thought it would make a good little post.

This can be done using fn_dblog, or if the relevant log isn’t available on the system any more, using fn_dump_dblog, albeit more slowly.

The two pieces of information needed are the user and the rough time that the transaction occurred.

The user can’t be used to search in the log directly, but every LOP_BEGIN_XACT log record contains the SID of who ran the transaction. The SID can be obtained from the username using the SUSER_SID function (remember that it’s more complicated if someone’s used EXECUTE AS, as that can mask who they really are – details in this post).

For instance, on my laptop:

SELECT SUSER_SID ('APPLECROSS\PAUL') AS [SID];
GO

SID
-----------------------------------------------------------------
0x0105000000000005150000008E888D4129BB677CAA278B76E8030000

Then you can use that SID as a filter for fn_dblog (or fn_dump_dblog), like so:

SELECT
	[Current LSN],
	[Operation],
	[Transaction ID],
	[Begin Time],
	LEFT ([Description], 40) AS [Description]
FROM
	fn_dblog (NULL, NULL)
WHERE
	[Transaction SID] = SUSER_SID ('APPLECROSS\PAUL');
GO

Current LSN             Operation                       Transaction ID Begin Time               Description
----------------------- ------------------------------- -------------- ------------------------ ----------------------------------------
00000021:0000049d:0001  LOP_BEGIN_XACT                  0000:000006c8  2015/06/03 11:18:13:790  Backup:CommitDifferentialBase;0x01050000
00000021:000004a5:0001  LOP_BEGIN_XACT                  0000:000006c9  2015/06/03 11:18:13:810  Backup:CommitLogArchivePoint;0x010500000
00000021:000004a5:0002  LOP_BEGIN_XACT                  0000:000006ca  2015/06/03 11:18:13:810  Backup:CommitLogArchivePoint;0x010500000
00000021:000004a7:0003  LOP_BEGIN_XACT                  0000:000006cb  2015/06/03 11:18:13:820  INSERT;0x0105000000000005150000008e888d4
00000021:000004a7:0004  LOP_BEGIN_XACT                  0000:000006cc  2015/06/03 11:18:13:820  AllocHeapPageSimpleXactDML;0x01050000000
00000021:000004a7:0007  LOP_BEGIN_XACT                  0000:000006cd  2015/06/03 11:18:13:820  AllocFirstPage;0x01050000000000051500000
00000021:000004ad:0002  LOP_BEGIN_XACT                  0000:000006ce  2015/06/03 11:18:13:820  INSERT;0x0105000000000005150000008e888d4
00000021:000004ae:0001  LOP_BEGIN_XACT                  0000:000006cf  2015/06/03 11:18:16:112  INSERT;0x0105000000000005150000008e888d4
00000021:000004af:0001  LOP_BEGIN_XACT                  0000:000006d0  2015/06/03 11:19:17:306  INSERT;0x0105000000000005150000008e888d4
00000021:000004b0:0001  LOP_BEGIN_XACT                  0000:000006d1  2015/06/03 11:22:35:451  DELETE;0x0105000000000005150000008e888d4
00000021:000004b1:0001  LOP_BEGIN_XACT                  0000:000006d2  2015/06/03 11:27:42:998  INSERT;0x0105000000000005150000008e888d4
00000021:000004b2:0001  LOP_BEGIN_XACT                  0000:000006d3  2015/06/03 11:29:56:044  DELETE;0x0105000000000005150000008e888d4

.
.
.

Obviously the transactions above are a contrived example. You can imagine the case of lots of transactions spread out over a few hours (or even over a day, being investigated through log backups with fn_dump_dblog) and to narrow it down to the transaction you want you could look through the list manually for the rough time or specify a time range on the SELECT using predicates on the Begin Time column in the fn_dblog output.

For example:

SELECT
	[Current LSN],
	[Operation],
	[Transaction ID],
	[Begin Time],
	LEFT ([Description], 40) AS [Description]
FROM
	fn_dblog (NULL, NULL)
WHERE
	[Transaction SID] = SUSER_SID ('APPLECROSS\PAUL')
AND ([Begin Time] > '2015/06/03 11:18:15' AND [Begin Time] < '2015/06/03 11:18:25');
GO

Current LSN             Operation                       Transaction ID Begin Time               Description
----------------------- ------------------------------- -------------- ------------------------ ----------------------------------------
00000021:000004ae:0001  LOP_BEGIN_XACT                  0000:000006cf  2015/06/03 11:18:16:112  INSERT;0x0105000000000005150000008e888d4
00000021:000004af:0001  LOP_BEGIN_XACT                  0000:000006d0  2015/06/03 11:19:17:306  INSERT;0x0105000000000005150000008e888d4
00000021:000004b0:0001  LOP_BEGIN_XACT                  0000:000006d1  2015/06/03 11:22:35:451  DELETE;0x0105000000000005150000008e888d4

And if you knew what the operation was, you could narrow it down by the Description too.

Then it’s a simple case of taking the Current LSN of the LOP_BEGIN_XACT log record of the transaction you’re interested in, and restoring a copy of the database using the STOPBEFOREMARK trick (that I showed in my previous post on using this stuff) to restore to a point just before that transaction.

Enjoy!

Posted in: Backup/Restore, Disaster Recovery, Transaction Log, Undocumented commands
14 Comments

More on using Transaction SID from the transaction log

By: Paul Randal
Posted on: February 11, 2014 6:54 am

Back in 2012 I blogged about using fn_dblog and fn_dump_dblog to figure out the point at which something occurred that you’d like to restore to just before (e.g. a table drop). I also mentioned that you can use the SUSER_SNAME () function on on the [Transaction SID] column for the LOP_BEGIN_XACT log record of the operation to find out who performed the operation.

Yesterday in our IE2 Performance Tuning class in Tampa, someone asked me what the [Transaction SID] column would show if someone had run EXECUTE AS. As I wasn’t 100% certain, I decided to test and write a quick blog post.

First off I’ll set up a database and table to use:

USE [master];
GO
CREATE DATABASE [Test];
GO
ALTER DATABASE [Test] SET RECOVERY SIMPLE;
GO
USE [Test];
GO
CREATE TABLE [TestTable] ([c1] INT IDENTITY);
GO
INSERT INTO [TestTable] DEFAULT VALUES;
GO 5

Next I’ll create a Kimberly user for a SQL login, and a Katelyn user for a Windows login:

-- Create Kimberly login and user
CREATE LOGIN [KimberlyLogin] WITH PASSWORD = 'NiceWife';
CREATE USER [KimberlyUser] FOR LOGIN [KimberlyLogin];
EXEC sp_addrolemember N'db_owner', N'KimberlyUser';
GO

-- Create Katelyn user
CREATE USER [KatelynUser] FOR LOGIN [APPLECROSS\Katelyn];
EXEC sp_addrolemember N'db_owner', N'KatelynUser';
GO

Now I’ll delete a single row as me and each of the users and logins:

-- Delete as me
DELETE FROM [TestTable] WHERE [c1] = 1;
GO

-- Now delete as Kimberly user
EXECUTE AS USER = N'KimberlyUser';
DELETE FROM [TestTable] WHERE [c1] = 2;
REVERT;
GO

-- Now delete as Kimberly login
EXECUTE AS LOGIN = N'KimberlyLogin';
DELETE FROM [TestTable] WHERE [c1] = 3;
REVERT;
GO

-- Now delete as Katelyn user
EXECUTE AS USER = N'KatelynUser';
DELETE FROM [TestTable] WHERE [c1] = 4;
REVERT;
GO

-- Now delete as Katelyn login
EXECUTE AS LOGIN = N'APPLECROSS\Katelyn';
DELETE FROM [TestTable] WHERE [c1] = 5;
REVERT;
GO

Finally I’ll pull the [Transaction SID] for each of the delete operations and pass it into SUSER_SNAME ():

SELECT
	[Operation], [Transaction Name], [Transaction SID],
	SUSER_SNAME ([Transaction SID]) AS [WhoDidIt?]
FROM fn_dblog (NULL, NULL)
WHERE [Operation] = N'LOP_BEGIN_XACT'
AND [Transaction Name] = 'DELETE';
GO

Operation       Transaction Name  Transaction SID                                             WhoDidIt?
--------------- ----------------- ----------------------------------------------------------- -------------------
LOP_BEGIN_XACT  DELETE            0x0105000000000005150000003A5014D05A957BF8F5C8882EE8030000  APPLECROSS\paul
LOP_BEGIN_XACT  DELETE            0x9A9A69BEACF67E4994E2F2DEE35BC02F                          KimberlyLogin
LOP_BEGIN_XACT  DELETE            0x9A9A69BEACF67E4994E2F2DEE35BC02F                          KimberlyLogin
LOP_BEGIN_XACT  DELETE            0x0105000000000005150000003A5014D05A957BF8F5C8882EFE030000  APPLECROSS\Katelyn
LOP_BEGIN_XACT  DELETE            0x0105000000000005150000003A5014D05A957BF8F5C8882EFE030000  APPLECROSS\Katelyn

So the answer is that the log record contains the SID of who you’re executing as. The only way to tell who is really running the code would be through auditing.

Enjoy!

Posted in: Disaster Recovery, Transaction Log, Undocumented commands
6 Comments

Real world story of DBCC PAGE saving the day

By: Paul Randal
Posted on: September 19, 2013 1:20 pm

Last week I answered a question on Twitter about DBCC PAGE and asked if I could be sent more details about the problem. The person was gracious enough to send me a detailed explanation, and it’s such an interesting scenario that I asked for and received permission to share this cut-down, anonymous version of the story with you.

Basically, it’s a real-world application of using DBCC PAGE to solve a nasty business problem that couldn’t be solved any other way.

The company involved produces government-regulated medical products, where tracking products and their ingredients is absolutely critical to make sure that any problems with materials leads to the affected products being withdrawn to prevent possible loss of life.

The company has an electronic document management application that stores all the tracking documents about all the ingredients, processes, and products. Earlier this year the application started to suffer performance problems, which turned out to be running out of threads in the connection pool. The vendor fix was to reboot. This cleared the problem, but then it started again. Rinse and repeat. After a few cycles of this, the performance problems started appearing more and more frequently after the reboot, leading to lots of complaints.

The DBA got involved and noticed a bunch of blocked sessions, each blocked by unresolved DTC transactions, holding locks on table records. As more records became locked on each reboot, blocking got worse and worse.

The solution? Rollback the DTC transactions.

The problem? These DTC transactions in some cases were days old, and some documents tied to those transactions had already been destroyed. Rolling back the DTC transactions would have meant questionable integrity of large amounts of product inventory, thus endangering patients. It might have been possible to check through everything by hand, but that would have been a prohibitively expensive effort.

DBCC PAGE to the rescue. Using the DMVs, the DBA figured out all the X-locked records and dumped all the associated pages (about 50) with DBCC PAGE dump style 3. By working with the application vendor and the application admin, the information in the records allowed the exact documents involved to be determined, and further querying of the application database confirmed that the documents had indeed been successfully imported. This meant all the hung transactions could be safely terminated.

The ability to look into the pages and figure out which documents were involved saved the company from having to write off a ton of inventory.

Bottom line: undocumented commands are *NOT* just for the intellectual interest of poking about in the internals or for dealing with corruption.

Posted in: Undocumented commands
8 Comments