Get SQL query in logon trigger

Question

I have a requirement for a logon trigger. I need to capture the SQL query that is coming to SQL Server from an Excel Pivot file.

Currently I am using the following code:

CREATE TRIGGER [MyLogonTrigger] ON ALL SERVER FOR LOGON
AS 
BEGIN
    IF PROGRAM_NAME() <> 'Microsoft%'

    DECLARE @sqltext VARBINARY(128)
    SELECT @sqltext = sql_handle
    FROM sys.sysprocesses
    WHERE spid = @@spid

    DECLARE @SQLQuery varchar(MAX)
    set @SQLQuery = (select TEXT
    FROM sys.dm_exec_sql_text(@sqltext))

    INSERT INTO TestDatabase.dbo.LogonAudit 
             (
                    ... audit columns ...
             ) 
       Select
                    SUSER_SNAME()
                    ,GETDATE()
                    ,@@SPID
                    ,PROGRAM_NAME()
                    ,ORIGINAL_DB_NAME()
                    ,HOST_NAME()
                    ,client_net_address
                    ,@SQLQuery
   FROM sys.dm_exec_connections 
   WHERE session_id = @@SPID
END;

The problem I am facing is that @SQLQuery is the Create Trigger definition code every time, and not the actual query that is passed to SQL from the Excel file when the pivot is refreshed.

I think this has something to do with the fact that the login and the actual select query execution happens on two different transactions (SPID's).

Any idea how I can get the actual select query which excel uses to retrieve the data in a login trigger?

Answer 1

As Brent Ozar noted in his answer, you are attempting to use a Logon trigger for a purpose for which it was not designed. Logon triggers are typically used to either capture details about who is logging onto the server, or to deny particular combinations of users/machines etc from connecting.

Luckily, Extended Events offers a mechanism for capturing T-SQL in memory that, when configured correctly, can be fairly light on system resources.

I've used something like the following code in the past to capture T-SQL from a particular user or machine:

IF EXISTS 
(
    SELECT 1 
    FROM sys.server_event_sessions dxs 
    WHERE dxs.name = 'queries'
)
BEGIN
    IF EXISTS (
        SELECT 1 
        FROM sys.dm_xe_sessions dxs 
        WHERE dxs.name = 'queries'
    )
    BEGIN
        ALTER EVENT SESSION queries 
        ON SERVER 
        STATE = STOP;
    END
    DROP EVENT SESSION queries 
    ON SERVER;
END

CREATE EVENT SESSION queries ON SERVER 
ADD EVENT sqlserver.sql_statement_starting
(
    ACTION 
    (
        package0.collect_system_time
        , package0.event_sequence /* SQL Server 2012+ */
        , sqlserver.client_app_name
        , sqlserver.client_hostname
        , sqlserver.database_name /* SQL Server 2012+ */
        , sqlserver.plan_handle
        , sqlserver.sql_text
        , sqlserver.username
        , sqlserver.request_id
        , sqlserver.session_id
    )
    WHERE sqlserver.username = N'some_user_name'
        AND sqlserver.database_id = 6 /* track a specific database only */
        AND sqlserver.client_hostname <> 'excluded_host_name'
) 
, ADD EVENT sqlserver.sql_statement_completed
(
    ACTION 
    (
        package0.collect_system_time
        , package0.event_sequence /* SQL Server 2012+ */
        , sqlserver.client_app_name
        , sqlserver.client_hostname
        , sqlserver.database_name /* SQL Server 2012+ */
        , sqlserver.plan_handle
        , sqlserver.sql_text
        , sqlserver.username
        , sqlserver.request_id
        , sqlserver.session_id
    )
    WHERE sqlserver.username = N'some_user_name'
        AND sqlserver.database_id = 6 
        AND sqlserver.client_hostname <> 'excluded_host_name'
) 
, ADD EVENT sqlserver.error_reported 
(
    ACTION 
    (
        package0.collect_system_time
        , package0.event_sequence /* SQL Server 2012+ */
        , sqlserver.client_app_name
        , sqlserver.client_hostname
        , sqlserver.database_name /* SQL Server 2012+ */
        , sqlserver.plan_handle
        , sqlserver.sql_text
        , sqlserver.username
        , sqlserver.request_id
        , sqlserver.session_id
    )
    WHERE sqlserver.username = N'some_user_name'
        AND sqlserver.database_id = 6 
        AND sqlserver.client_hostname <> 'excluded_host_name'
        /* fluff errors below - for SQL Server 2008 R2, use "error" instead of "error_number" */
        AND error_number <> 5703 /* Changed language setting to %.*ls. */
        AND error_number <> 5701 /* Changed database context to '%.*ls'. */
        AND error_number <> 2528 /* DBCC execution completed. If DBCC printed error messages, contact 
                            your system administrator. */
        AND error_number <> 7969 /* No active open transactions. */
        AND error_number <> 4035 /* Processed %I64d pages for database '%ls', file '%ls' on file %d. */
        AND error_number <> 18265/* Log was backed up. Database: %s, creation date(time): %s(%s), 
                first LSN: %s, last LSN: %s, number of dump devices: %d, device information: (%s). 
                This is an informational message only. No user action is required. */
        AND error_number <> 3014 /* %hs successfully processed %I64d pages in %d.%03d seconds (%d.%03d MB/sec). */
        AND error_number <> 14570/* (Job outcome) */
        AND error_number <> 8153 /* Warning: Null value is eliminated by an aggregate or other SET operation. */
)
ADD TARGET package0.ring_buffer
(
    SET max_memory = 1024
)
/* add or remove the below target as required. */
, ADD TARGET package0.asynchronous_file_target
(
    SET filename = 'C:\temp\queries_xe_target.xel'
        , max_file_size = 10        /* max size in MB */
        , max_rollover_files = 10
        , increment = 1             /* file growth increment in MB */
)
/* Don't start this Extended Events session automatically when the server starts */
WITH 
(
    STARTUP_STATE = OFF                                 /* Extended Event Session will NOT be automatically 
                                                            started at server startup */
    , TRACK_CAUSALITY = ON
    , MAX_MEMORY = 5MB                                  /* buffer size to use */
    , EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS    /* ALLOW_MULTIPLE_EVENT_LOSS or NO_EVENT_LOSS */
    , MAX_DISPATCH_LATENCY = 15 SECONDS                 /* maximum number of seconds until buffer contents 
                                                            are written to the target */
    , MEMORY_PARTITION_MODE = PER_NODE                  /* NONE, PER_NODE, PER_CPU */
);
GO

Use this to start the session as required:

IF EXISTS 
(
    SELECT 1 
    FROM sys.server_event_sessions dxs 
    WHERE dxs.name = 'queries'
)
BEGIN
    ALTER EVENT SESSION queries ON SERVER STATE = START;
END

This shows the session target details:

SELECT SessionName = xe.name
    , TargetName = xet.target_name
    , EventData = CONVERT(xml, xet.target_data)
FROM sys.dm_xe_session_targets AS xet
    INNER JOIN sys.dm_xe_sessions AS xe ON (xe.address = xet.event_session_address)
WHERE xe.name = 'queries';

Use this to see the results from the ring buffer:

DECLARE @xml XML;

SELECT TOP(1) @xml = CONVERT(xml, xet.target_data)
FROM sys.dm_xe_session_targets AS xet
    INNER JOIN sys.dm_xe_sessions AS xe ON (xe.address = xet.event_session_address)
WHERE xe.name = 'queries'
    AND xet.target_name = 'ring_buffer';

IF OBJECT_ID('tempdb..#xmlResults') IS NOT NULL
DROP TABLE #xmlResults;

CREATE TABLE #xmlResults
(
    RowNum INT NOT NULL
        PRIMARY KEY CLUSTERED
        IDENTITY(1,1)
    , xeXML XML NOT NULL
);

INSERT INTO #xmlResults (xeXML)
SELECT xm.s.query('.')
FROM @xml.nodes('/RingBufferTarget/event') AS xm(s)
OPTION (Optimize FOR (@xml = Null)); -- immensely improves performance in SQL Server 2008

SELECT t.EventName
    , DateStamp = DATEADD(HOUR, -6, t.EventDateStamp)
    , DatabaseName = d.name
    , t.ErrorNumber
    , t.ErrorSeverity
    , t.ErrorState
    , t.ErrorMessage
    , t.CollectSystemTime
    , t.ClientAppName
    , t.ClientHostName
    , t.PlanHandle
    , t.SqlText
    , t.UserName
FROM (
        SELECT EventName =          xeXML.value('(event/@name)[1]','varchar(500)')
            , EventDateStamp =      xeXML.value('(event/@timestamp)[1]','datetime')
            , DatabaseID =          xeXML.value('(event/data[(@name)[1] eq "source_database_id"]/value/text())[1]','varchar(255)')
            , ErrorNumber =         xeXML.value('(event/data[(@name)[1] eq "error"]/value/text())[1]','varchar(255)')
            , ErrorSeverity =       xeXML.value('(event/data[(@name)[1] eq "severity"]/value/text())[1]','varchar(255)')
            , ErrorState =          xeXML.value('(event/data[(@name)[1] eq "state"]/value/text())[1]','varchar(255)')
            , ErrorMessage =        xeXML.value('(event/data[(@name)[1] eq "message"]/value/text())[1]','varchar(255)')
            , CollectSystemTime =   xeXML.value('(event/action[(@name)[1] eq "collect_system_time"]/text/text())[1]','varchar(255)')
            , ClientAppName =       xeXML.value('(event/action[(@name)[1] eq "client_app_name"]/value/text())[1]','varchar(255)')
            , ClientHostName =      xeXML.value('(event/action[(@name)[1] eq "client_hostname"]/value/text())[1]','varchar(255)')
            , PlanHandle =          CONVERT(xml, xeXML.value('(event/action[(@name)[1] eq "plan_handle"]/value/text())[1]','varchar(255)')).value('(plan/@handle)[1]', 'varchar(255)')
            , SqlText =             xeXML.value('(event/action[(@name)[1] eq "sql_text"]/value/text())[1]','nvarchar(max)')
            , UserName =            xeXML.value('(event/action[(@name)[1] eq "username"]/value/text())[1]','varchar(128)')
        FROM #xmlResults xm
    ) t
    LEFT JOIN sys.databases d ON t.DatabaseID = d.database_id
WHERE t.UserName NOT IN (
      'user_1'  COLLATE SQL_Latin1_General_CP1_CI_AS
    , 'user_2'  COLLATE SQL_Latin1_General_CP1_CI_AS
    , 'user_3'  COLLATE SQL_Latin1_General_CP1_CI_AS
    ) 
ORDER BY t.UserName
    , t.EventDateStamp;

SELECT *
FROM #xmlResults

Answer 2

Login triggers can't be used for auditing queries. I can log in and then run several queries in a row.

For auditing select statements, you'll need to use things like:

• Auditing - built into SQL Server, but requires Enterprise Edition (before SQL Server 2016 SP1)
• Profiler traces - also built in, but has a really heavy performance overhead
• Third party tools like Idera SQL Compliance Manager (I have no association with that product, just heard from a lot of happy users)

Answer 3

Logon triggers happen before SQL Server ever sees any query text passed by the user (think about a dentist trying to examine your X-ray before turning the X-ray machine on). They need to authenticate prior to being allowed to submit any queries, and just to clarify, when a login has authenticated and issues multiple queries during their session, their session_id (SPID in the old days) does not change.

It's important to note that it is called a logon trigger (something that fires in response only to the act of logging on), as opposed to a login trigger (something that fires whenever a server principal - otherwise known as a login - performs some action).

Rather than think about this as a problem of "I need to log something as soon as any query runs," why not take advantage of things SQL Server already tracks? You didn't mention version, but sys.dm_exec_query_stats in modern versions will tell you all the queries that have been run recently, and if you poll it frequently enough, you can log all instances of queries along with aggregated metrics. Assuming there is something the queries from Excel have in common, you can isolate those by parsing the query text or going even further and linking to dependent objects.

SELECT [Query] = SUBSTRING(st.[text],(qs.statement_start_offset + 2) / 2,
        (CASE 
            WHEN qs.statement_end_offset = -1 
             THEN LEN(CONVERT(nvarchar(max), st.text)) * 2
             ELSE qs.statement_end_offset + 2
            END - qs.statement_start_offset) / 2),
  qs.execution_count,
  qs.total_elapsed_time,
  average_time = qs.total_elapsed_time * 1.0 / qs.execution_count  
FROM sys.dm_exec_query_stats AS qs
CROSS APPLY sys.dm_exec_sql_text(qs.plan_handle) AS st
--WHERE st.[text] LIKE N'%some object or schema relevant to Excel%';

A couple of other quick notes:

• checking PROGRAM_NAME() should use NOT LIKE as opposed to <>. This should be APP_NAME() anyway (PROGRAM_NAME() is undocumented and unsupported).
• as @AMtwo pointed out, you need BEGIN/END after IF if you have more than one statement after the conditional check (though I think you should always have BEGIN/END no matter how many statements follow).
• you shouldn't be using sysprocesses anymore. This is deprecated, and provided - at least for now - only for backward compatibility with legacy code.