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

DJAdan 671 Reputation points
2021-03-22T19:49:53.017+00:00

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://learn.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
SQL Server
A family of Microsoft relational database management and analysis systems for e-commerce, line-of-business, and data warehousing solutions.
12,690 questions
Transact-SQL
Transact-SQL
A Microsoft extension to the ANSI SQL language that includes procedural programming, local variables, and various support functions.
4,552 questions
0 comments
Accepted answer
  1. Erland Sommarskog 100.9K Reputation points MVP
    2021-03-22T20:05:14.177+00:00

    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://learn.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.

    0 comments

2 additional answers

Sort by: Most helpful
Most helpful Newest Oldest
  1. DJAdan 671 Reputation points
    2021-03-22T21:02:39.423+00:00

    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

  2. DJAdan 671 Reputation points
    2021-03-23T17:35:52.24+00:00

    Hi Erland,

    Very helpful, as always.

    --Dan

    0 comments