question

DJAdan-4490 avatar image
0 Votes"
DJAdan-4490 asked DJAdan-4490 answered

SQL SERVER Logon Trigger Failing for error codes: #18056 and #17892

Hi All,

Version: Microsoft SQL Server 2017 (RTM-CU20) (KB4541283) - 14.0.3294.2 (X64) Mar 13 2020 14:53:45 Copyright (C) 2017 Microsoft Corporation Enterprise Edition: Core-based Licensing (64-bit) on Windows Server 2016 Standard 10.0 <X64> (Build 14393: ) (Hypervisor)

Reference: https://docs.microsoft.com/en-us/answers/questions/200954/best-practice-which-database-should-i-use-when-cre.html

This is a follow-up question to the question answered in the above referenced Forum entry. <thank you, that was very helpful!>

I implemented the attached logon trigger and it has been running with no errors in our development environment for the past 3 months.
Today I installed it in our production environment and it partially worked, but also logged thousands of failures. I don't understand why.


When I say "partially", it logged some 100's of user connections but failed on most.

Within the first minute, I got thousands of errors that look like this:

03/22/2021 10:01:09,spid645,Unknown,The client was unable to reuse a session with SPID 645<c/> which had been reset for connection pooling. The failure ID is 1. >This error may have been caused by an earlier operation failing. Check the error logs for failed operations immediately before this error message.
03/22/2021 10:01:09,spid645,Unknown,Error: 18056<c/> Severity: 20<c/> State: 1.
03/22/2021 10:01:09,Logon,Unknown,Logon failed for login 'XXX_user' due to trigger execution. [CLIENT: www.xxx.yyy.zzz]
03/22/2021 10:01:09,Logon,Unknown,Error: 17892<c/> Severity: 20<c/> State: 1.

I had to disable and drop the trigger from production.

I never received any errors like this on my development server. The only thing I can think of is that the production environment is very busy, where as development is relatively quiet all day. My TRY/CATCH print messages never appear in the error log, so I don't know where things were going wrong.

sp_helprotect output on my target table looks like this:

80310-capture.png

Any thoughts?

Thank you for any insight you might provide.

--Dan

 if (exists (select * from master.sys.server_triggers where type = 'TR' and name = 'my_trigger') )
 begin
                 drop trigger my_trigger on all server;
 end;
 go
    
 /**
  **    SQL Server LOGON TRIGGER:    my_trigger
  **
  **    Abstract:
  **                This LOGON TRIGGER is designed to log all connections to an audit table contained in the master database.
  **
  **                The table name is master..sql_server_login_audit_t
  **
  ** Note:
  **
  **        This TRIGGER executes under the username LoginTrigger.  This Login has VIEW SERVER STATE Permission which is required
  **        to select from sys.dm_exec_connections.
  **
  **        CREATE LOGIN LoginTriggerUser WITH PASSWORD = 'xxxxxxxxxx';
  **        ALTER LOGIN LoginTriggerUser DISABLE;
  **        CREATE USER LoginTriggerUser For LOGIN LoginTriggerUser;
  **        GRANT select,insert,update,delete ON sql_server_login_audit_t TO LoginTriggerUser;
  **        GRANT VIEW SERVER STATE to LoginTriggerUser;
  **
  **        Useful SQL commands ...
  **        DISABLE TRIGGER my_trigger ON ALL SERVER;
  **        ENABLE TRIGGER my_trigger ON ALL SERVER;
  **        DROP TRIGGER my_trigger ON ALL SERVER;
    
  **----------------------------------------------------------------------------------------------------------------------------------
  **/
     
 create trigger [my_trigger] 
 on all server 
 with execute as 'LoginTriggerUser'  -- use LoginTriggerUser because it has VIEW SERVER STATE permission, which is required for sys.dm_exec_connections
 for logon
    
 as
 begin
    
     set nocount on;
        
     declare
         @Login_Name                    varchar(60),
         @Client_Net_Address            varchar(60),
         @Host_Name                    varchar(60),
         @Program_Name                varchar(255),
         @Client_Interface_Name        varchar(255),
         @Now                         datetime,
         @SecondsSinceStarted        bigint,
         @SqlServerStartSeconds        bigint = 300;    -- 5 minutes (60 seconds * 5 minutes)
    
     /*
      *    Check to see if SQL Server has just restarted.  If so, allow immediate connection without logging.  The assumption is that we don't want the
      *    trigger to get overwhelmed with thousands of xxx reconnections all at once.
      */
      select 
         @SecondsSinceStarted = datediff(second, si.sqlserver_start_time, getdate())
     from 
         sys.dm_os_sys_info si;
    
     if ( @SecondsSinceStarted < @SqlServerStartSeconds ) return;
    
     /*
      *    Check if the incoming connection SPID is a user process.  If not, get out of here quietly.
      */
            
     if (exists (
                 select * 
                 from 
                     sys.dm_exec_sessions s 
                     inner join sys.dm_exec_connections c on (s.session_id = c.session_id)
                 where
                     s.is_user_process = 1
                     and s.session_id = @@SPID
                     and upper(s.host_name) not in ('HOST1','HOST2','HOST3','HOST4','HOST5','HOST6','HOST7')
                 )
         )
     /*
      *    If we got this far, we are a valid user_process.   Let's get some key identifying information
      */
     begin
         select 
             @Login_Name = ORIGINAL_LOGIN(),
             @Client_Net_Address = c.client_net_address,
             @Host_Name = s.host_name,
             @Program_Name = s.program_name,
             @Client_Interface_Name = s.client_interface_name,
             @Now = getdate()
         from
             sys.dm_exec_sessions s
                 inner join sys.dm_exec_connections c on (s.session_id = c.session_id)
         where
             s.session_id = @@SPID;
    
         /*
          *    Check to see if we've seen this connection before ... if so, update the # of attempts, and login_dt
          */
         if (exists (
                     select *
                     from
                         master.dbo.sql_server_login_audit_t
                     where
                         login_name = @Login_Name
                         and host_name = @Host_Name
                         and client_net_address = @Client_Net_Address
                         and program_name = @Program_Name
                         and client_interface_name = @Client_Interface_Name
                     )
            )
         begin
             begin try
                 update master.dbo.sql_server_login_audit_t
                     set
                         attempts = attempts + 1,
                         login_dt = @Now,
                         current_spid = @@SPID
                 where
                     login_name = @Login_Name
                     and host_name = @Host_Name
                     and client_net_address = @Client_Net_Address
                     and program_name = @Program_Name
                     and client_interface_name = @Client_Interface_Name;    
             end try
             begin catch
                 print 'Failed to UPDATE sql_server_login_audit_t: ' + @Program_Name + ', login ' + @Login_Name + 
                                              ', Error ' + convert(varchar(50),    ERROR_NUMBER()) + ', Error Msg ' + ERROR_MESSAGE();
             end catch
         end;
         else
         /*
          *    Ok, this is a new connection, so let's log it to our table and start tracking it.
          */
         begin
             begin try
                 insert into master.dbo.sql_server_login_audit_t (login_name, host_name, client_net_address, program_name, client_interface_name, attempts, login_dt, current_spid)
                 values 
                 (
                     @Login_Name,
                     @Host_Name,
                     @Client_Net_Address,
                     @Program_Name,
                     @Client_Interface_Name,
                     1,
                     @Now,
                     @@SPID
                 );
             end try
             begin catch
                 print 'Failed to insert sql_server_login_audit_t: ' + @Program_Name + ', login ' + @Login_Name + 
                                              ', Error ' + convert(varchar(50),    ERROR_NUMBER()) + ', Error Msg ' + ERROR_MESSAGE();
             end catch
         end;
            
     end;
    
 end;
 go


sql-server-generalsql-server-transact-sql
capture.png (8.1 KiB)
5 |1600 characters needed characters left characters exceeded

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.

ErlandSommarskog avatar image
0 Votes"
ErlandSommarskog answered

Do you really want to record pooled connections? Most applications today connect, submit a query or two and then disconnect. The client API then lingers to that connection, and keeps it open for another 60 seconds. If the application reconnects within that time frame with the same connection string, the API reuses the connection. It does however pass a bit on the TDS packet to tell SQL Server to clean up the connection, and it does count as a login and will fire your login trigger.

What really happened in your logon trigger I don't know, but if the system is busy and you don't have good indexes on your audit table, I can guess on deadlock or other accidents.

I think you should use the eventdata() function to get information about the login, and return silently if IsPooled = 1. This function can also give you some if not all the details you are getting from DMVs. See https://docs.microsoft.com/en-us/sql/relational-databases/triggers/capture-logon-trigger-event-data?view=sql-server-ver15.

If you only log logins with IsPooled = 0, you are logging only true new physical logins. Less load, and less noise in your audit table.

5 |1600 characters needed characters left characters exceeded

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.

DJAdan-4490 avatar image
0 Votes"
DJAdan-4490 answered ErlandSommarskog commented

Hi Erland,

Thanks for your quick response!

Are you suggesting I could quickly and silently ignore all incoming Pooled Connections with the following code fragment inserted after line 53 (above)?

     declare
         @EventDataXml                xml;
    
     set
         @EventDataXml = EVENTDATA();
    
     if (@EventDataXml.value('(/EVENT_INSTANCE/IsPooled)[1]', 'nvarchar(1)') = 1) return;

Thanks for your help!

--Dan

· 1
5 |1600 characters needed characters left characters exceeded

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.

Yes, this is what I had in mind. Although, I would use bit rather than nvarchar(1), but that's a detail.

And not only "could", but also "should". I don't think you want to audit every pooled reconnection.

0 Votes 0 ·
DJAdan-4490 avatar image
0 Votes"
DJAdan-4490 answered

Hi Erland,

Very helpful, as always.

--Dan

5 |1600 characters needed characters left characters exceeded

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.