Thursday, April 24, 2008

Auditing Data Modification Statements Using Trigger

Here is an interesting problem: how to audit data modification statements against a table? The goal is to log the SQL executed to modify the table using a trigger. Of course, SELECT statements cannot be logged since only INSERT/UPDATE/DELETE can invoke a trigger. One way to implement this is using a server side trace (which actually can capture the SELECT statements too), however that brings unnecessary overhead.

The following query will get the current SQL statement in SQL Server 2005.

SELECT [text]

FROM sys.dm_exec_requests AS R

CROSS APPLY sys.dm_exec_sql_text(plan_handle) AS S

WHERE session_id = @@SPID;



However, when executed in a trigger body it simply returns the CREATE TRIGGER statement, not the actual modification SQL statement. A better approach that works is using DBCC INPUTBUFFER. The only tricky part is that the DBCC output cannot be directly saved to a table. The workaround is to use INSERT EXEC to execute DBCC INPUTBUFFER as dynamic SQL and insert the results to a table. Here is the complete solution.

-- SQL log table

CREATE TABLE SQLLog (

 language_event NVARCHAR(100),

 parameters INT,

 event_info NVARCHAR(4000),

 event_time DATETIME DEFAULT CURRENT_TIMESTAMP);

 

-- Sample table to audit actions for

CREATE TABLE Foo (

 keycol INT PRIMARY KEY,

 datacol CHAR(1));

 

-- Sample data

INSERT INTO Foo VALUES (1, 'a');

INSERT INTO Foo VALUES (2, 'b');

INSERT INTO Foo VALUES (3, 'c');

 

GO

 

-- Audit trigger

CREATE TRIGGER LogMySQL

ON Foo

AFTER INSERT, UPDATE, DELETE

AS

 INSERT INTO SQLLog (language_event, parameters, event_info)

 EXEC('DBCC INPUTBUFFER(@@SPID);');

GO

 

-- Perform some logged actions

GO

 

INSERT INTO Foo VALUES (4, 'd');

 

GO

 

DELETE Foo

WHERE keycol = 1;

 

GO

 

UPDATE Foo

SET datacol = 'f'

WHERE keycol = 2;

 

GO

 

-- Perform non-logged action

-- SELECT cannot be logged

SELECT datacol

FROM Foo

WHERE keycol = 4;

 

GO

 

-- Check what we have in the log

SELECT event_info, event_time

FROM SQLLog;

 

/*

 

-- Results

 

event_info                                        event_time

--------------------------------                 -----------------------

INSERT INTO Foo VALUES (4, 'd');                 2008-04-24 22:24:31.153

DELETE Foo WHERE keycol = 1;                     2008-04-24 22:24:31.170

UPDATE Foo SET datacol = 'f' WHERE keycol = 2;    2008-04-24 22:24:31.170

 

*/



It is good to note here that DBCC INPUTBUFFER requires the user executing to be member of the sysadmin fixed server role. One way to handle this is to specify user or login with sufficient privileges in EXEC (by using EXEC AS LOGIN or USER:

INSERT INTO SQLLog (language_event, parameters, event_info)

EXEC('DBCC INPUTBUFFER(@@SPID);') AS LOGIN = 'admin_login';

5 comments:

Anonymous said...

Excellent. This article address and issue I am facing now. Execution time is critical in a high volume system. Brad

Joe Doherty said...

Superb piece of information!
Thank you very much.

Brendan said...

Plamen, I've run into an issue with this sugestion.

I'm doing essentialy the same thing, except I'm running the INSERT/EXEC on a temporary table inside the trigger.

The event_info being returned is still the trigger CREATE code, not the command which caused the trigger to fire.

Any ideas why?

Thanks in advance.

Brendan said...

Ack, scratch that. I posted too soon. After far too long spent tearing my hair out, I realized I had made a very stupid mistake.

Another block of code trying to get the query text was left _below_ the working code, and overwrote the correct text. Duh.

So, now I feel like an idiot, but at least my trigger works!

Thanks, Plamen!

Anonymous said...

THANKS