How to find out Security Errors on SQL Server 2005 instance and above including the API call it failed on

More often than not, while troubleshooting SQL Server Security Issues, you end up performing post-mortem analysis. Under such circumstances, the Ring Buffer output comes in handy because it stores the Security Errors that were reported in the past for a certain period of time. 

For an example, let’s say if you tried to create a SQL Login with the Password Policy enabled and provided a password that didn’t match a password policy, then you will receive an error stating that the password is not complex enough. This error will be stored in the ring buffer. When you execute the query below, you will find out the SPID that raised the error along with the API Name that is failing. In the sample output for this scenario described above, you will find that the NetValidatePwdPolicy failed. 

If you convert the ErrorCode value 0x8C5 (= 2245) to decimal and do a NET HELPMSG <number> from command prompt, you will find more information on why that error occurred. 

Output of NET HELPMSG 2245: 

The password does not meet the password policy requirements. Check the minimum password length, password complexity and password history requirements. 

The Calling API Name and the API Name are very helpful when troubleshooting Domain Account related security errors as it would call functions related to Directory Services whose documentation can be found on Tech Net which would make your troubleshooting easier. 

Sample Output: 

Notification_time: 2009-11-06 08:37:08.023
ErrorCode: 0x8C5             
CallingAPIName: NetValidatePwdPolicy                                       
APIName: NetValidatePwdPolicy                         
SPID: 53       
Record Id: 0           
Type: RING_BUFFER_SECURITY_ERROR                          
 

For SQL Server 2005: 

SELECT CONVERT (varchar(30), GETDATE(), 121) as runtime,
DATEADD (ms, -1 * ((sys.cpu_ticks / sys.cpu_ticks_in_ms) - a.[Record Time]), GETDATE()) AS Notification_time, 
a.* , sys.ms_ticks AS [Current Time]
FROM
(SELECT
x.value('(//Record/Error/ErrorCode)[1]', 'varchar(30)') AS [ErrorCode],
x.value('(//Record/Error/CallingAPIName)[1]', 'varchar(255)') AS [CallingAPIName],
  x.value('(//Record/Error/APIName)[1]', 'varchar(255)') AS [APIName],
x.value('(//Record/Error/SPID)[1]', 'int') AS [SPID],
x.value('(//Record/@id)[1]', 'bigint') AS [Record Id],
x.value('(//Record/@type)[1]', 'varchar(30)') AS [Type],
x.value('(//Record/@time)[1]', 'bigint') AS [Record Time]
FROM (SELECT CAST (record as xml) FROM sys.dm_os_ring_buffers
WHERE ring_buffer_type = 'RING_BUFFER_SECURITY_ERROR') AS R(x)) a
CROSS JOIN sys.dm_os_sys_info sys
ORDER BY a.[Record Time] ASC

 For SQL Server 2008

SELECT CONVERT (varchar(30), GETDATE(), 121) as runtime,
dateadd (ms, (a.[Record Time] - sys.ms_ticks), GETDATE()) as [Notification_Time],
a.* , sys.ms_ticks AS [Current Time]
FROM
(SELECT
x.value('(//Record/Error/ErrorCode)[1]', 'varchar(30)') AS [ErrorCode],
x.value('(//Record/Error/CallingAPIName)[1]', 'varchar(255)') AS [CallingAPIName],
  x.value('(//Record/Error/APIName)[1]', 'varchar(255)') AS [APIName],
x.value('(//Record/Error/SPID)[1]', 'int') AS [SPID],
x.value('(//Record/@id)[1]', 'bigint') AS [Record Id],
x.value('(//Record/@type)[1]', 'varchar(30)') AS [Type],
x.value('(//Record/@time)[1]', 'bigint') AS [Record Time]
FROM (SELECT CAST (record as xml) FROM sys.dm_os_ring_buffers
WHERE ring_buffer_type = 'RING_BUFFER_SECURITY_ERROR') AS R(x)) a
CROSS JOIN sys.dm_os_sys_info sys
ORDER BY a.[Record Time] ASC

  

Additional Reference 

http://blogs.msdn.com/psssql/archive/2008/03/24/how-it-works-sql-server-2005-sp2-security-ring-buffer-ring-buffer-security-error.aspx

Advertisement

How to track exceptions using Ring Buffers output

SQL Server 2005 added a new feature called Dynamic Management Views (DMVs) to help DBAs monitor the server. However, people like me who were comfortable using the system tables available in SQL Sever 2000 (read: averse to change 😉 ) took quite a bit of time to switch over to using DMVs. One such DMV that has caught on with making live troubleshooting much easier is the sys.dm_os_ring_buffers DMV. The ring buffers hold historical information about events occurring on the server. Recently, I was working on a lock timeout issue. Based on a profiler trace capture, it was found that the server was experiencing multiple occurrences of the following message: 

Lock request time out period exceeded.  

We identified the statements and made the changes to prevent the Lock Timeout from occurring. Now that the server was being monitored, I didn’t want to a run a SQL Server profiler trace to track the occurrence of this message. So, I thought of using the Ring Buffers DMV to monitor if any further Lock Timeouts were occurring the server. This made monitoring the instance a piece of cake! 

The script below will give you the time range between which the exceptions are stored in the Ring Buffers along with the list of exception occurrences that you want to monitor. 

SQL Server 2005 

------------- Script Start -----------------------
DECLARE @ts_now BIGINT,@dt_max BIGINT, @dt_min BIGINT
SELECT @ts_now = cpu_ticks / CONVERT(FLOAT, cpu_ticks_in_ms) FROM sys.dm_os_sys_info
select @dt_max = MAX(timestamp), @dt_min = MIN(timestamp) from sys.dm_os_ring_buffers WHERE ring_buffer_type = N'RING_BUFFER_EXCEPTION'
select DATEADD(ms, -1 * (@ts_now - @dt_max), GETDATE()) AS MaxTime,
DATEADD(ms, -1 * (@ts_now - @dt_min), GETDATE()) AS MinTime
SELECT record_id,
DATEADD(ms, -1 * (@ts_now - [timestamp]), GETDATE()) AS EventTime,y.Error,UserDefined,b.description as NormalizedText
FROM (
SELECT
                        record.value('(./Record/@id)[1]', 'int') AS record_id,
                        record.value('(./Record/Exception/Error)[1]', 'int') AS Error,
                        record.value('(./Record/Exception/UserDefined)[1]', 'int') AS UserDefined,TIMESTAMP
FROM (
SELECT TIMESTAMP, CONVERT(XML, record) AS record
FROM sys.dm_os_ring_buffers
WHERE ring_buffer_type = N'RING_BUFFER_EXCEPTION'
AND record LIKE '% %') AS x) AS y
INNER JOIN sys.sysmessages b
on y.Error = b.error
WHERE b.msglangid = 1033 and  y.Error = 1222 -- Change the message number to the message number that you want to monitor
ORDER BY record_id DESC
------------- Script End -----------------------

 

SQL Server 2008 

------------- Script Start -----------------------
DECLARE @ts_now BIGINT,@dt_max BIGINT, @dt_min BIGINT
SELECT @ts_now = cpu_ticks / CONVERT(FLOAT, ms_ticks) FROM sys.dm_os_sys_info
select @dt_max = MAX(timestamp), @dt_min = MIN(timestamp) from sys.dm_os_ring_buffers WHERE ring_buffer_type = N'RING_BUFFER_EXCEPTION'
select DATEADD(ms, -1 * (@ts_now - @dt_max), GETDATE()) AS MaxTime,
DATEADD(ms, -1 * (@ts_now - @dt_min), GETDATE()) AS MinTime
SELECT record_id,
DATEADD(ms, -1 * (@ts_now - [timestamp]), GETDATE()) AS EventTime,Error,UserDefined,text as NormalizedText
FROM (
SELECT
                        record.value('(./Record/@id)[1]', 'int') AS record_id,
                        record.value('(./Record/Exception/Error)[1]', 'int') AS Error,
                        record.value('(./Record/Exception/UserDefined)[1]', 'int') AS UserDefined,TIMESTAMP
FROM (
SELECT TIMESTAMP, CONVERT(XML, record) AS record
FROM sys.dm_os_ring_buffers
WHERE ring_buffer_type = N'RING_BUFFER_EXCEPTION'
AND record LIKE '% %') AS x) AS y
INNER JOIN sys.messages b
on y.Error = b.message_id
WHERE b.language_id = 1033 and  y.Error = 1222 -- Change the message number to the message number that you want to monitor
ORDER BY record_id DESC
------------- Script End -----------------------

 

Technorati Tags: ,,,

How to find out the CPU usage information for the SQL Server process using Ring Buffers

SQL Server 2005 Ring Buffers stored information related to CPU usage. This information is updated every 1 minute. So at any given point of time you can trace back the CPU usage for 4 hours 15 minutes. A sample output below shows the SQL instance CPU utilization against the other processes (active on the server) CPU utilization. This will definitely help us identify whether the SQL Server process is actually driving CPU. 

Sample Output:

Event Time SQL Process Utilization System Idle Other Process Utilization
2009-11-19 20:00:49.947  0 96 4
2009-11-19 19:59:49.933  0 92 8
2009-11-19 19:58:49.910  0 91 9
2009-11-19 19:57:49.893  0 92 8

For SQL Server 2005: 

declare @ts_now bigint 

select @ts_now = cpu_ticks / convert(float, cpu_ticks_in_ms) from sys.dm_os_sys_info 

select record_id, 

dateadd(ms, -1 * (@ts_now - [timestamp]), GetDate()) as EventTime, 

SQLProcessUtilization, 

SystemIdle, 

100 - SystemIdle - SQLProcessUtilization as OtherProcessUtilization 

from ( 

select 

record.value('(./Record/@id)[1]', 'int') as record_id, 

record.value('(./Record/SchedulerMonitorEvent/SystemHealth/SystemIdle)[1]', 'int') as SystemIdle, 

record.value('(./Record/SchedulerMonitorEvent/SystemHealth/ProcessUtilization)[1]', 'int') as SQLProcessUtilization, 

timestamp 

from ( 

select timestamp, convert(xml, record) as record 

from sys.dm_os_ring_buffers 

where ring_buffer_type = N'RING_BUFFER_SCHEDULER_MONITOR' 

and record like '%<SystemHealth>%') as x 

) as y 

order by record_id desc

For SQL Server 2008: 

declare @ts_now bigint 

select @ts_now = ms_ticks from 

sys.dm_os_sys_info 

select record_id, dateadd (ms, (y.[timestamp] -@ts_now), GETDATE()) as EventTime,




SQLProcessUtilization, 

SystemIdle, 

100 - SystemIdle - SQLProcessUtilization as OtherProcessUtilization 

from ( 

select 

record.value('(./Record/@id)[1]', 'int') as record_id, 

record.value('(./Record/SchedulerMonitorEvent/SystemHealth/SystemIdle)[1]', 'int') 

as SystemIdle, 

record.value('(./Record/SchedulerMonitorEvent/SystemHealth/ProcessUtilization)[1]', 

'int') as SQLProcessUtilization, 

timestamp 

from ( 

select timestamp, convert(xml, record) as record 

from sys.dm_os_ring_buffers 

where ring_buffer_type = N'RING_BUFFER_SCHEDULER_MONITOR' 

and record like '%<SystemHealth>%') as x 

) as y 

order by record_id desc