seo/sqlinsight-pro
1
0
Fork 0
Code Issues Pull requests Projects Releases 11 Packages Wiki Activity Actions

Review 1.2: error log entries are no longer counted again

Browse source 
The default trace was filtered on whole seconds only, so the newest entry
read (ReadUntil) came back at every collection until a newer one was
written: one 824 became a new event every 5 minutes. Entries at or before
ReadUntil are now left out, as for xp_readerrorlog.

The ring buffer's times were computed to whole seconds from the clock at
each read and moved by up to a second between reads, so the newest entry
could be counted twice. They are now computed to the millisecond with a
small tolerance.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Søren Eggert Lundsteen Olsen 2026-10-02 11:31:00 +02:00
parent 1bbe5eb8eb
commit 70934e7562
1 changed files with 15 additions and 5 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

20
src/SQLInsight.Collectors/Instance/ErrorLogCollector.cs
View file

@ -16,14 +16,19 @@ public sealed class ErrorLogCollector(int loginFailureBurst = 20) : Collector<Er
/// <summary>On the first collection, this far back.</summary>
public static readonly TimeSpan FirstLookBack = TimeSpan.FromHours(1);
/// <summary>How much the ring buffer's computed times can move between two reads.</summary>
internal static readonly TimeSpan RingBufferClockTolerance = TimeSpan.FromMilliseconds(50);
internal const string CanReadErrorLogSql = """
SELECT CASE WHEN IS_SRVROLEMEMBER(N'securityadmin') = 1 OR IS_SRVROLEMEMBER(N'sysadmin') = 1 THEN 1 ELSE 0 END,
DATEDIFF(minute, GETUTCDATE(), GETDATE()), GETUTCDATE()
""";
// The exception ring buffer: every exception raised, with number and severity. ms_ticks is the clock it counts in.
// The time is computed to the millisecond: rounded to whole seconds it moved by up to a second between collections,
// so the newest entry could be read (and counted) again.
internal const string RingBufferSql = """
SELECT DATEADD(second, -CAST((i.ms_ticks - rb.timestamp) / 1000 AS int), GETUTCDATE()),
SELECT DATEADD(millisecond, -CAST((i.ms_ticks - rb.timestamp) % 1000 AS int), DATEADD(second, -CAST((i.ms_ticks - rb.timestamp) / 1000 AS int), GETUTCDATE())),
rb.x.value('(//Exception/Error)[1]', 'int'), rb.x.value('(//Exception/Severity)[1]', 'int')
FROM (SELECT timestamp, CAST(record AS xml) AS x FROM sys.dm_os_ring_buffers WHERE ring_buffer_type = N'RING_BUFFER_EXCEPTION') rb
CROSS JOIN sys.dm_os_sys_info i
@ -31,7 +36,7 @@ public sealed class ErrorLogCollector(int loginFailureBurst = 20) : Collector<Er
// Failed logins in the connectivity ring buffer (SQL Server 2008+): error 18456 with its state and client address.
internal const string ConnectivitySql = """
SELECT DATEADD(second, -CAST((i.ms_ticks - rb.timestamp) / 1000 AS int), GETUTCDATE()),
SELECT DATEADD(millisecond, -CAST((i.ms_ticks - rb.timestamp) % 1000 AS int), DATEADD(second, -CAST((i.ms_ticks - rb.timestamp) / 1000 AS int), GETUTCDATE())),
rb.x.value('(//SniConsumerError)[1]', 'int'), rb.x.value('(//State)[1]', 'int'), rb.x.value('(//RemoteHost)[1]', 'nvarchar(128)')
FROM (SELECT timestamp, CAST(record AS xml) AS x FROM sys.dm_os_ring_buffers
WHERE ring_buffer_type = N'RING_BUFFER_CONNECTIVITY' AND record LIKE N'%<SniConsumerError>18456</SniConsumerError>%') rb
@ -74,12 +79,15 @@ public sealed class ErrorLogCollector(int loginFailureBurst = 20) : Collector<Er
}
else
{
// The ring buffer's times are derived from the server's clock at each read and can differ by a few
// milliseconds between reads (datetime precision), so the newest entry read last time must not be read again.
var after = since + RingBufferClockTolerance;
entries = (await Db.QueryAsync(connection, RingBufferSql, r => new ErrorLogEntry(Utc(r.DateTime(0)), r.NullableInt(1), r.NullableInt(2), null), ct)
.ConfigureAwait(false)).Where(e => e.At > since).ToList();
.ConfigureAwait(false)).Where(e => e.At > after).ToList();
if (context.Instance.Version.Major >= 10)
{
entries.AddRange((await Db.QueryAsync(connection, ConnectivitySql, r => new ErrorLogEntry(Utc(r.DateTime(0)), 18456, 14,
$"Login failed (state {r.NullableInt(2)}) [CLIENT: {r.NullableString(3)}]"), ct).ConfigureAwait(false)).Where(e => e.At > since));
$"Login failed (state {r.NullableInt(2)}) [CLIENT: {r.NullableString(3)}]"), ct).ConfigureAwait(false)).Where(e => e.At > after));
}
(source, coverage) = (ErrorLogSource.RingBuffer, RingBufferCoverage);
@ -154,7 +162,9 @@ public sealed class ErrorLogCollector(int loginFailureBurst = 20) : Collector<Er
}
}
return entries;
// StartTime is compared to whole seconds above, so the entries of that second that were read last time
// (the newest of them is ReadUntil) come back; leave them out, or they are counted again every collection.
return [.. entries.Where(e => e.At > since)];
}
catch (DbException)
{