Server Audit Mystery 2: Filtering action_id gets Error Msg 25713

(last updated: 2018-06-05)

This post is, for the most part, a continuation of Server Audit Mystery 1: Filtering class_type gets Error Msg 25713. In that post I was trying to filter on the class_type field / predicate source (i.e. the object, or whatever, that the event is on). The tricky part was that class_type is supposed to be filterable on string values such as U for “User Table”, P for “Stored Procedure”, etc. But, the reality is that it has to be filtered using numbers, and that list does not seem to be documented anywhere. Fortunately, I was able to find the list of possible numbers, so all is well with regards to class_type.

When it comes to the action_id field, however, we are not so lucky. It, too, should be filterable on the string codes that are returned by sys.database_audit_specification_details and sys.fn_get_audit_file. But, just like class_type, only numbers can be used for filtering. And, like class_type, that list of numbers does not seem to be documented anywhere. But, unlike class_type, I cannot find any list of numbers (in SQL Server) that corresponds to the available actions. I did find a list of statements by looking at Extended Events info (since Audits use Extended Events):

SELECT *
FROM   sys.dm_xe_map_values
WHERE  [name] = N'statement_type';

but it wasn’t the correct list. So, this means that I have to go hunting for these values the even-harder way

Search Attempt #1

Given that the values for class_type were all between 8257 and 22868 (i.e. well within the positive range of SMALLINT), I figured that the values for action_id would be in a similar range. My plan was to set up a test that audits just the EXECUTE action and check each value from 0 through 65535 (i.e. the total range of SMALLINT, which is also the maximum value of an unsigned Int16). I would do this test by looping through each of those values, and for each one, I would:

  1. Disable the Audit (Audits cannot be altered while enabled)
  2. Alter the Audit to set the filter predicate to the next value
  3. Enable the Audit
  4. Execute a Stored Procedure that does not do anything
  5. Disable the Audit (Audits have a minimum 1 second delay โ€” configurable, but not to less than 1 second โ€” to queue one or more events before writing to the log. But, disabling the Audit causes the queue to flush immediately to the log, thus no delay ๐Ÿ˜‰ ).
  6. Read the log to see if an event had been recorded (the audit file name is partially made up of the Server Audit name and audit_guid, but also includes additional characters that aren’t as easy to predict. The full path does exist in the sys.dm_server_audit_status DMV, but that record only exists while the Audit is enabled, and this Server Audit was disabled in the previous step. It is probably easy enough to grab the full path from that DMV when the test script enables the Audit, but there is a much easier method that already exists: the sys.fn_get_audit_file DMF allows you to pass in a filename pattern that uses DOS wildcard characters, so you only need to specify the path and name of the Server Audit. Specifying just the path would allow for reading all audit files in that path at the same time, and that might throw off the test):
    1. If any rows exist in the audit file, then break out of the loop since we have the answer (this is easy to check since I set the Server Audit to use only 1 file, which will be reused each time. And, every time the Server Audit is enabled, the file is cleared out to start over).
    2. Else, increment the test value and try again.

First we run the one-time steps to create both the Server Audit and the Database Audit Specification. Previously we didn’t need the Database Audit Specification in order to figure out that the class_type and action_id fields could only be filtered on numbers since the filter is part of the Server Audit. I, however, did use a Database Audit Specification to confirm that the list of numbers I found was correct, even though setting that up was not shown in the previous post. But, here we need that second piece since we are doing more than just validation. We need it in order to find the values in the first place.

SETUP

USE [master];

CREATE SERVER AUDIT [TestAuditFilter]
TO FILE 
(
    FILEPATH = N'C:\TEMP\', -- ' extra quote to fix blog code formatting
    MAX_ROLLOVER_FILES = 1
);
GO

USE [tempdb];

CREATE DATABASE AUDIT SPECIFICATION [DatabaseAuditToTestFiltering]
FOR SERVER AUDIT [TestAuditFilter]
ADD (EXECUTE ON DATABASE::[tempdb] BY [public])
WITH (STATE = ON);

EXEC(N'
CREATE PROCEDURE dbo.DoNothing
AS
RETURN;
');

EXEC dbo.DoNothing; -- test
GO

Now that the required pieces have been created, we can cycle through the values until we find the one that traps the EXECUTE action:

TEST

USE [master];

DECLARE @Number INT = 1, -- starting value
        @Template NVARCHAR(MAX) = N'ALTER SERVER AUDIT [TestAuditFilter]
WHERE ([action_id] = {tmpNumber});',
        @Query NVARCHAR(MAX);

ALTER SERVER AUDIT [TestAuditFilter]
WITH (STATE = OFF); -- ensure 1st loop does not fail from enabled audit

WHILE (@Number < 65536)
BEGIN
    IF (@Number % 100 = 0)
    BEGIN
        RAISERROR('Number: %d', 10, 1, @Number) WITH NOWAIT;
    END;

    SET @Query = REPLACE(@Template, N'{tmpNumber}',
                             CONVERT(NVARCHAR(10), @Number));
    EXEC (@Query); -- alter filter with new number


    ALTER SERVER AUDIT [TestAuditFilter]
    WITH (STATE = ON); -- enable audit

    EXEC [tempdb].[dbo].[DoNothing];

    ALTER SERVER AUDIT [TestAuditFilter]
    WITH (STATE = OFF); -- force immediate write to log file

    IF (EXISTS(SELECT *
    FROM sys.fn_get_audit_file(N'C:\TEMP\TestAuditFilter*', NULL, NULL)))
    BEGIN
        SELECT @Number AS [Found!];
        BREAK;
    END;

    SET @Number += 1;
END; /* WHILE */

After the script had been running for 75 minutes, I noticed that it was processing 470 – 500 values per minute. That rate translates to a total time of between 130 and 140 minutes to complete. To be clear, that’s 2 hours and 10 minutes (at least) to find a single value. AND, that assumes that I was correct in estimating that the range was 0 – 65,535. So I cancelled the query.

Search Attempt #2

A thought crossed my mind: I could verify the overall range by using a predicate of

[action_id] >= 0 AND [action_id] <= 2147483647

I initially used a value of 2147483648 for the upper-limit to see if the value was BIGINT. I received an “arithmetic overflow” error. I was then able to use 2147483647 as planned, hence we know that the value is an INT.

I ran a test and this time a row was logged in the audit file. I then updated the range by removing the initial “2” leaving me with an upper-limit of 147483647. Running the test again did not produce a row in the audit file. Ruh-roh (as Scooby Doo says). It looks like testing each value, starting at 1 and testing 500 per minute, was going to take somewhere close to forever to complete. And again, that is just for a single value.

I needed a completely new approach. Fortunately, testing a large range (like I was doing directly above) appeared to be a very promising way to narrow down the possible values. All I needed was a way to start out with the full range, and then narrow the range down by half each time. That would have a very limited number of iterations, somewhere around 32 since 232 = 2147483648.

Search Attempt #3

I finally came up with the following stored procedure to test each action. It has parameters to pass in the string version of the action_id, and the test query. There are too many different actions, and too much variation in the potential setup needed to cause the action (e.g. creating a table in order to perform an UPDATE) to have predefined query batches, so that needs to be passed-in.

USE [master];
IF (OBJECT_ID(N'tempdb..##DiscoverActionID') IS NOT NULL)
BEGIN
    DROP PROCEDURE ##DiscoverActionID;
END;
GO

CREATE PROCEDURE ##DiscoverActionID
(
    @Action VARCHAR(10),
    @TestQuery NVARCHAR(MAX)
)
AS
SET NOCOUNT ON;

DECLARE @LowNumber INT = 0,
        @HighNumber INT = 2147483647,
        @Template NVARCHAR(MAX) = N'ALTER SERVER AUDIT [TestAuditFilter]
WHERE ([action_id] >= {LowNumber} AND [action_id] <= {HighNumber});',
        @AlterQuery NVARCHAR(MAX),
        @OldHighNum INT,
        @Counter INT = 1;

ALTER SERVER AUDIT [TestAuditFilter]
WITH (STATE = OFF); -- ensure 1st loop does not fail from enabled audit

WHILE (1 = 1)
BEGIN
    RAISERROR('( %2d ) Low / High: %d ; %d', 10, 1,
                  @Counter, @LowNumber, @HighNumber) WITH NOWAIT;

    SET @AlterQuery = REPLACE(
                    REPLACE(@Template,
                     N'{LowNumber}', CONVERT(NVARCHAR(10), @LowNumber)),
                     N'{HighNumber}', CONVERT(NVARCHAR(10), @HighNumber));
    EXEC (@AlterQuery); -- alter filter with new numbers

    ALTER SERVER AUDIT [TestAuditFilter]
    WITH (STATE = ON); -- enable audit

    EXEC (@TestQuery);

    ALTER SERVER AUDIT [TestAuditFilter]
    WITH (STATE = OFF); -- force immediate write to log file

    IF (EXISTS(SELECT *
        FROM  sys.fn_get_audit_file(N'C:\TEMP\TestAuditFilter*', NULL, NULL)
        WHERE [action_id] = @Action))
    BEGIN
        IF (@LowNumber = @HighNumber)
        BEGIN
            BREAK;
        END;

        SET @OldHighNum = @HighNumber;
        SET @HighNumber = ((@HighNumber - @LowNumber) / 2) + @LowNumber;
    END;
    ELSE
    BEGIN
        IF (@OldHighNum IS NULL)
        BEGIN
            RAISERROR('Action not present!', 16, 1);
            RETURN -1;
        END;
        SET @LowNumber = (@HighNumber + 1);
        SET @HighNumber = ((@OldHighNum - @LowNumber) / 2) + @LowNumber;
    END;

    SET @Counter += 1;
END; /* WHILE (1 = 1) */

PRINT CHAR(13) + CHAR(10) + 'FOUND: ' + CONVERT(VARCHAR(10), @HighNumber);
GO

Initial Testing

With the Stored Procedure created, we can now take it out for a “test drive”. Executing the following:

EXEC ##DiscoverActionID N'EX', N'EXEC [tempdb].[dbo].[DoNothing];';

returns the following:

(  1 ) Low / High:          0 ; 2147483647
(  2 ) Low / High:          0 ; 1073741823
(  3 ) Low / High:          0 ;  536870911
(  4 ) Low / High:  536870912 ;  805306367
(  5 ) Low / High:  536870912 ;  671088639
(  6 ) Low / High:  536870912 ;  603979775
(  7 ) Low / High:  536870912 ;  570425343
(  8 ) Low / High:  536870912 ;  553648127
(  9 ) Low / High:  536870912 ;  545259519
( 10 ) Low / High:  536870912 ;  541065215
( 11 ) Low / High:  536870912 ;  538968063
( 12 ) Low / High:  538968064 ;  540016639
( 13 ) Low / High:  538968064 ;  539492351
( 14 ) Low / High:  538968064 ;  539230207
( 15 ) Low / High:  538968064 ;  539099135
( 16 ) Low / High:  538968064 ;  539033599
( 17 ) Low / High:  538968064 ;  539000831
( 18 ) Low / High:  538968064 ;  538984447
( 19 ) Low / High:  538984448 ;  538992639
( 20 ) Low / High:  538984448 ;  538988543
( 21 ) Low / High:  538988544 ;  538990591
( 22 ) Low / High:  538990592 ;  538991615
( 23 ) Low / High:  538990592 ;  538991103
( 24 ) Low / High:  538990592 ;  538990847
( 25 ) Low / High:  538990592 ;  538990719
( 26 ) Low / High:  538990592 ;  538990655
( 27 ) Low / High:  538990656 ;  538990687
( 28 ) Low / High:  538990656 ;  538990671
( 29 ) Low / High:  538990656 ;  538990663
( 30 ) Low / High:  538990656 ;  538990659
( 31 ) Low / High:  538990660 ;  538990661
( 32 ) Low / High:  538990660 ;  538990660
( 33 ) Low / High:  538990661 ;  538990661

FOUND: 538990661

Those 33 steps took all of 4 seconds! That’s quite an improvement.

Additional Testing

In order to test more actions other than just EXECUTE, they need to be added to the Database Audit Specification. This can be done in SQL Server Management Studio (SSMS), or executing the following T-SQL:

USE [tempdb];

ALTER DATABASE AUDIT SPECIFICATION [DatabaseAuditToTestFiltering]
WITH (STATE = OFF);

ALTER DATABASE AUDIT SPECIFICATION [DatabaseAuditToTestFiltering]
ADD (INSERT, UPDATE, DELETE, SELECT ON DATABASE::[tempdb] BY [public]);

ALTER DATABASE AUDIT SPECIFICATION [DatabaseAuditToTestFiltering]
WITH (STATE = ON);
GO

After that, we use the following query to get the string audit_id values that need to be passed into the Stored Procedure:

SELECT *
FROM   tempdb.sys.database_audit_specification_details dasd
INNER JOIN tempdb.sys.database_audit_specifications das
        ON das.[database_specification_id] =
           dasd.[database_specification_id]
WHERE  das.[name] = N'DatabaseAuditToTestFiltering';

And with those audit_id values we can run the following tests to find their corresponding INT values (all of which are posted in a chart in the following section):

CREATE TABLE tempdb.dbo.InsTest ([Col1] INT);
EXEC ##DiscoverActionID N'IN', N'INSERT INTO tempdb.dbo.InsTest
([Col1]) VALUES (1);';
DROP TABLE tempdb.dbo.InsTest;
-- 33 steps

CREATE TABLE tempdb.dbo.InsTest ([Col1] INT);
EXEC ##DiscoverActionID N'DL', N'DELETE FROM tempdb.dbo.InsTest;';
DROP TABLE tempdb.dbo.InsTest;
-- 32 steps

CREATE TABLE tempdb.dbo.InsTest ([Col1] INT);
EXEC ##DiscoverActionID N'UP', N'UPDATE tempdb.dbo.InsTest
SET [Col1] = 1;';
DROP TABLE tempdb.dbo.InsTest;
-- 33 steps

CREATE TABLE tempdb.dbo.InsTest ([Col1] INT);
EXEC ##DiscoverActionID N'SL',
     N'IF EXISTS(SELECT * FROM tempdb.dbo.InsTest) PRINT 1;';
DROP TABLE tempdb.dbo.InsTest;
-- 33 steps

Please note that the test queries in each case produce no output. The only output from the Stored Procedure should be the 32 or 33 steps and the final value. Even the SELECT test at end does an IF EXISTS for a condition that will never be true, so the PRINT statement is never executed.

Also, values that end up being an even number take 32 steps while odd values take 33 steps.

Available Actions

To see the full list of Database-level “actions”, run the following query:

SELECT  [action_id], [name], [class_desc], [covering_parent_action_name],
        [configuration_level], [containing_group_name]
FROM    [sys].[dm_audit_actions]
WHERE   N'DATABASE' IN ([parent_class_desc], [class_desc])
ORDER BY [name], [class_desc];

Please note that there is repetition of some action_id and name values since many of them can apply to different classes (ex: Database, Schema, Object, Role, etc).

To see just the distinct actions, run the following query:

SELECT   DISTINCT [action_id], [name]
FROM     [sys].[dm_audit_actions]
ORDER BY [name];

I found 158 distinct actions on SQL Server 2017.

Filterable action_id Numbers

Of the 158 actions, I have mapped 6 of them for use with Server Audit filtering:

action_id (string) name action_id (Number)
AUSC AUDIT SESSION CHANGED 1129534785
DL DELETE 538987588
EX EXECUTE 538990661
IN INSERT 538988105
SL SELECT 538987603
UP UPDATE 538988629

Final Thoughts

Given that the actual numeric value for “Execute” is 538990661, my attempt #1 โ€” starting at 1 and processing at a rate of 500 per minute โ€” would have taken:

  • 1,077,981.32 minutes
  • which is 17,966.36 hours
  • which is 748.60 days
  • which is 2 years and 18 days

Yikes! And again, that is just for one value!! I very much prefer the 4 seconds of the updated approach. Yay refactoring ๐Ÿ™‚ !!

If anyone knows of an easier method, or a location where they are already mapped, please let me know. Also, if anyone has time to map any of the remaining 152 actions, please let me know what they are so I can add them to the list.

Also see:

UPDATE 2018-06-05

I just found a blog post from October, 2012 that I missed in my initial investigation into this error:

Filter SQL Server Audit on action_id / class_type predicate

In that post, Rinku shows that the numeric “action_id” values are actually derivable from the string “action_id” values. With this in mind, it is possible to apply that algorithm to all of the string “action_id” values in [sys].[dm_audit_actions]. A function is provided in that post that converts the string values into their numeric equivalents. I reduced / simplified that function into the dbo.GetIntActionID function shown below, which is logically equivalent to the original:

USE [tempdb];
GO
/*
  By Solomon Rutzky ( June 5, 2018 )

  Simplified version of "dbo.GetInt_action_id" by Rinku Agarwal
    ( October 3, 2012 )
*/

-- DROP FUNCTION dbo.GetIntActionID;
CREATE FUNCTION dbo.GetIntActionID(@ActionID VARCHAR(4))
RETURNS INT
WITH SCHEMABINDING
BEGIN

SET @ActionID = UPPER(@ActionID);

DECLARE @ReturnVal INT = ASCII(SUBSTRING(@ActionID, 1, 1));


SELECT @ReturnVal = @ReturnVal +
		(POWER(2, (8 * tmp.[num])) * ASCII(
			CONVERT(CHAR(1),   -- force blank if no character
				SUBSTRING(@ActionID, (1 + tmp.[num]), 1)
				   ))
		)
FROM   (VALUES (1), (2), (3)) tmp(num);


RETURN @ReturnVal;

END;
GO

I then used that function to calculate all of the values using the following query:

SELECT   DISTINCT
            [name],
            [action_id],
            dbo.GetIntActionID([action_id]) AS [ActionIdINT]
FROM     [sys].[dm_audit_actions]
ORDER BY [name];

Please note that some values returned by that query might have no effect as it is possible that some values might not show up in server audits. For example, the BATCH_COMPLETED_GROUP that became available in SQL Server 2016 is not in the “Audit Action Type” drop-down when managing Database Audit Specifications or Server Audit Specifications in SSMS (as of v17.7). It can be used in a ALTER DATABASE AUDIT SPECIFICATION [db_audit_spec_name] ADD (BATCH_COMPLETED_GROUP); statement, but if you do that, then you can no longer use the UI to manage that Audit Specification (you will get an “Object reference not set to an instance of an object” error).

To see the full list of values across SQL Server versions 2012, 2014, 2016, and 2017, please visit:

Server Audit Filter Values For [action_id]

Thoughts? Questions? Comments? Suggestions? Words of praise?

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 )

Google+ photo

You are commenting using your Google+ 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 )

w

Connecting to %s