How to capture sp_refreshsqlmodule event

Question

My issue: executing sp_refreshsqlmodule will update the sys.objects.modify_date value, but does not fire a DDL event that can be used by a DDL trigger. So if using a DDL trigger to show object change history, I cannot reconcile the reason that a procedure, function, etc. would have a recent modify_date when no ALTER statement has been run against the object. This can cause some headaches during audit time.

My question: Is there any way to capture sp_refreshsqlmodule event, so that I can have an automated way to reconcile the modify_date for database objects?

I was able to find this connect item for SQL Server 2008 https://connect.microsoft.com/SQLServer/feedback/details/340441/sp-autostats-and-other-system-procedures-does-not-fire-ddl-triggers , which is marked as closed with the comment:

we dont think it is critical to fix this for SQL Server 2008. We will definitely consider it for the release after that

I am able to replicate the issue in SQL Server 2014 as well.

SQL script to replicate the issue:

IF OBJECT_ID('dbo.test_DDL_log ') IS NOT NULL
DROP TABLE dbo.test_DDL_log; 
GO

CREATE TABLE dbo.test_DDL_log (id int not null identity primary key, DDL_EventData xml, dateCreated datetime, contextInfo varchar(128));
go

CREATE TRIGGER [TEST_ddlDatabaseTriggerLog] 
ON DATABASE 
FOR DDL_DATABASE_LEVEL_EVENTS 
AS 
--Log all DDL operations on this database to an audit table.
BEGIN
    SET NOCOUNT ON;

    INSERT INTO dbo.test_DDL_log(DDL_EventData, dateCreated, contextInfo)
    VALUES (
          EVENTDATA()
        , GETDATE()
        , REPLACE(CAST(CONTEXT_INFO() AS VARCHAR(128)), CHAR(0), '')
    );
END
GO 

--Context info used in DDL trigger to tie to build and/or Support Ticket # to this change
DECLARE @c varbinary(128);
SET @c=cast('Ticket 123 v1.2.345' as varbinary(128));
SET CONTEXT_INFO @c;
GO

--Repro Example taken from:  https://msdn.microsoft.com/en-us/library/bb326754.aspx
-- Create an alias type.
IF EXISTS (SELECT 'TEST_mytype' FROM sys.types WHERE name = 'TEST_mytype')
DROP TYPE TEST_mytype;
GO

CREATE TYPE TEST_mytype FROM nvarchar(5);
GO

IF OBJECT_ID ('dbo.TEST_to_upper', 'FN') IS NOT NULL
DROP FUNCTION dbo.TEST_to_upper;
GO

CREATE FUNCTION dbo.TEST_to_upper (@a TEST_mytype)
RETURNS TEST_mytype
WITH ENCRYPTION
AS
BEGIN
RETURN upper(@a)
END;
GO

-- Increase the length of the alias type.
EXEC sp_rename 'TEST_mytype', 'TEST_myoldtype', 'userdatatype';
GO

CREATE TYPE TEST_mytype FROM nvarchar(10);
GO

---- The function parameter still uses the old type.
-- and would Fail here because of truncation:
--SELECT dbo.TEST_to_upper('abcdefgh'); 
GO

select modify_date_BEFORE = o.modify_date
from sys.objects o 
where o.name = 'TEST_to_upper'
;
go

WAITFOR DELAY '00:00:05'; --allow some time to elapse so that modify_date change is more noticable
GO

-- Refresh the function to bind to the renamed type.
EXEC sys.sp_refreshsqlmodule 'dbo.TEST_to_upper';
go

select modify_date_AFTER = o.modify_date
from sys.objects o 
where o.name = 'TEST_to_upper'
;
go

--only 4 events show here, NOT included the call to sp_refreshsqlmodule which updated the modify_date
SELECT * from dbo.test_DDL_log;
go

--CLEANUP 
IF OBJECT_ID ('dbo.TEST_to_upper', 'FN') IS NOT NULL
DROP FUNCTION dbo.TEST_to_upper;
GO
IF EXISTS (SELECT 'TEST_myoldtype' FROM sys.types WHERE name = 'TEST_myoldtype')
DROP TYPE TEST_myoldtype;
GO
IF EXISTS (SELECT 'TEST_mytype' FROM sys.types WHERE name = 'TEST_mytype')
DROP TYPE TEST_mytype;
GO
if exists(select 1 from sys.triggers t where t.name = 'TEST_ddlDatabaseTriggerLog')
DROP TRIGGER [TEST_ddlDatabaseTriggerLog] ON DATABASE
GO

IF OBJECT_ID('dbo.test_DDL_log ') IS NOT NULL
DROP TABLE dbo.test_DDL_log; 
GO

Results of this script show:

modify_date_BEFORE
-----------------------
2015-10-16 10:59:10.447

modify_date_AFTER
-----------------------
2015-10-16 10:59:15.487

id          DDL_EventData                                                                                         dateCreated             contextInfo
----------- ------------------------------------------------------------------------------------------------ -------------------------    ------------------------
1           <EVENT_INSTANCE><EventType>CREATE_TYPE</EventType><PostTime>2015-10-16T10:59:10.443</PostTime>....... 2015-10-16 10:59:10.443 Ticket 123 v1.2.345
2           <EVENT_INSTANCE><EventType>CREATE_FUNCTION</EventType><PostTime>2015-10-16T10:59:10.447</PostTime>... 2015-10-16 10:59:10.447 Ticket 123 v1.2.345
3           <EVENT_INSTANCE><EventType>RENAME</EventType><PostTime>2015-10-16T10:59:10.450</PostTime>............ 2015-10-16 10:59:10.450 Ticket 123 v1.2.345
4           <EVENT_INSTANCE><EventType>CREATE_TYPE</EventType><PostTime>2015-10-16T10:59:10.453</PostTime>....... 2015-10-16 10:59:10.453 Ticket 123 v1.2.345

The event for the sp_refreshsqlmodule is nowhere to be found, and all logged events are prior to the sp_refreshsqlmodule time of 2015-10-16 10:59:15.487 (note: I put a 5 second delay prior to the sp_refreshsqlmodule call in the script above to make it more noticeable that this event was not being logged).

Answer 1

Unfortunately, there are several DDL-type events that don't actually count as DDL events for usage with DDL triggers, event notifications, etc.

You can capture sp_refreshsqlmodule calls using the following Extended Events session:

CREATE EVENT SESSION [refreshes] ON SERVER 
ADD EVENT sqlserver.module_end
(
  SET collect_statement = (1)
  ACTION
  (
     sqlserver.client_app_name, 
     sqlserver.client_hostname,
     sqlserver.database_id,
     sqlserver.database_name,
     sqlserver.username,
     sqlserver.context_info
  )
  WHERE ([object_id] = -419385653) -- OBJECT_ID(N'sys.sp_refreshsqlmodule')
)
ADD TARGET package0.asynchronous_file_target
(
  SET FILENAME = N'C:\temp\refreshes.xel'
);
GO

ALTER EVENT SESSION [refreshes] ON SERVER STATE = START;
GO

You may need to collect a different set of auditing columns; these were mostly just borrowed from a similar session I have. You may also want to add an additional filter for sp_refreshview and possibly other events like recompiles and statistics updates (I do not know all of the procedure calls that might change modify_date but aren't captured as proper DDL events).

Now, the session will merely capture the data. You can inspect it manually like this:

;WITH ee_data AS 
(
  SELECT x = CONVERT(XML, event_data)
    FROM sys.fn_xe_file_target_read_file
    (N'C:\temp\refreshes*.xel', NULL, NULL, NULL)
)
SELECT 
  [statement] = x.value('(event/data[@name="statement"]/value)[1]','nvarchar(4000)'),
  [timestamp] = x.value('(event/@timestamp)[1]','datetime2'),
  --username = x.value('(event/action[@name="username"]/value)[1]','nvarchar(400)'),
  --[host] = x.value('(event/action[@name="client_hostname"]/value)[1]','nvarchar(400)'),
  --app = x.value('(event/action[@name="client_app_name"]/value)[1]','nvarchar(400)')
  -- you'll have to add the xquery stuff to get context_info
FROM ee_data;

Example output:

statement                                      timestamp
--------------------------------------------   ---------------------------
EXEC sys.sp_refreshsqlmodule N'dbo.someview'   2015-10-16 16:45:35.6220000

You'll have to parse out the object name, and put the information into your own XML format to match EVENTDATA(). Also note that timestamp is in UTC, not your local time, so you'll need to adjust that for valid comparisons to modify_date (which inherit server time). In my case the difference between modify_date and timestamp was 6 milliseconds, so the session does not record the exact moment the object was modified - you'll need to allow a little leeway to "match" these two values.

You'll then need to put whatever code you end up with into some kind of job that polls the file target for new rows (you may consider query notifications for this to avoid polling, but polling is much simpler), and inserts them into your DDL auditing table.

Answer 2

@AaronBertrand's answer above works wells for SQL 2014 (and likely SQL 2012 although I don't have a 2012 instance to test against).

However, if using SQL Server 2008 R2, then you must remove the following lines when creating the event session, because they will cause the following errors:

SET collect_statement = (1) --error: Msg 25629, Level 16, State 1, For event, "sqlserver.module_end", the customizable attribute, "collect_statement", does not exist.
sqlserver.database_name  --within the ACTION block. Error: Msg 25623, Level 16, State 3, The event action name, "sqlserver.database_name", is invalid, or the object could not be found
sqlserver.context_info   --within the ACTION block. Error: Msg 25623, Level 16, State 3, The event action name, "sqlserver.context_info", is invalid, or the object could not be found

Since SET collect_statement does not work in SQL 2008 R2, then you must add sqlserver.sql_text to the Action list, and the code to parse the object name that was passed into sp_refreshsqlmodule would need to be able to handle multiple statements that were run in a batch.

Also in SQL2008R2, when filtering on the OBJECT_ID values in the where clause of the CREATE EVENT SESSION, you have to use positive object_id #'s for these system objects, even though the object_id #'s are actually negative. I'm guessing this is because in SQL 2008 R2 the extended events use uint32 internally for the object_id.

Here is the script for SQL 2008 R2:

CREATE EVENT SESSION [audit_sp_refreshes] ON SERVER 
--SQL SERVER 2008 R2 version
ADD EVENT sqlserver.module_end
(
  ACTION
  (
     sqlserver.client_app_name, 
     sqlserver.client_hostname,
     sqlserver.database_id,
     sqlserver.sql_text,
     sqlserver.username
  )
  WHERE 
    (
        --Must use POSITIVE object_id #'s here in SQL 2008 R2, even though the object_ids are actually negative
             [object_id] = 419385653  -- OBJECT_ID(N'sys.sp_refreshsqlmodule')
    ) 
)
ADD TARGET package0.asynchronous_file_target
(
  SET FILENAME = N'C:\TEMP\ExtendedEventLogs\audit_sp_refreshes.xel'
);
GO

ALTER EVENT SESSION [audit_sp_refreshes] ON SERVER STATE = START;
GO