SQL Logging

My logging framework for MSSQL now has a second version, and the trigger was a review of my own code, not a feature request. The first version, from my earlier post Ein Logging "Framework" für MSSQL (in German), is good enough for simple logging. As soon as I wanted to build reports on top of it, I ran into three limits, and a closer look also turned up real bugs.

This post shows what is new: runs with a run ID and a measured duration, structured error data, a buffer that survives a ROLLBACK, an Extended Events session as a safety net, and a single installation script with migration. It ends with what the framework deliberately cannot do.

What was wrong with version 1

Three weaknesses made reporting harder, and four real bugs came on top.

The three weaknesses

1. No run ID. Start and end entries could only be matched by procedure name and user. If two instances of the same procedure run in parallel under the same login, their runs get mixed up.
2. Duration only as free text. A Dauer: 123ms in AdditionalInfo can be parsed with SUBSTRING, but it is fragile.
3. Errors only as text. Error number, line and procedure were free text. Grouping by error type only worked through Message, and that often contains variable parts such as IDs or values.

The four bugs

• Caller detection: sys.dm_exec_calls with caller_id and call_stack_id does not exist in SQL Server, so the call-stack approach could never have worked. The @@PROCID fallback returns the logging procedure itself, not its caller.
• Missing schemas: INSERT INTO EventLog and EXEC LogEvent in Logging.Error did not name the schema and therefore resolve against the user's default schema.
• A missing GO before the first CREATE OR ALTER PROCEDURE.
• A result set on every call: with SELECT SCOPE_IDENTITY(), LogEvent sent a result set to the client on every log entry, which can disturb ADO code.

Runs instead of single rows: StartRun and EndRun

With Logging.StartRun and Logging.EndRun, every execution of a procedure gets its own run ID and a measured duration. StartRun pushes the run onto a stack in the SESSION_CONTEXT (key Logging.RunStack) and writes <NAME>_START. An entry consists of RunID, start time, run name and procedure name, with the newest on top. EndRun reads the start time from the stack, computes DurationMs, writes <NAME>_ABGESCHLOSSEN or <NAME>_FEHLER and pops the entry again. The suffixes are German ("completed" and "error") because they are part of the framework's existing naming convention, and the queries below rely on them.

Nested runs work because it is a stack: a child run carries the ParentRunID of its parent. Every ordinary call to Logging.Info, Warn, Error and Debug inside a run picks up the RunID and the procedure name from the stack automatically. You do not have to change existing calls for that.

CREATE OR ALTER PROCEDURE dbo.DatenImport @BatchId INT
AS
BEGIN
    SET NOCOUNT ON;
    SET XACT_ABORT ON;

    EXEC Logging.StartRun @Name = N'IMPORT', @ProcId = @@PROCID,
                          @AdditionalInfo = CONCAT(N'BatchId: ', @BatchId);
    BEGIN TRY
        EXEC Logging.Info @EventType = 'IMPORT_DETAIL', @Message = 'Validating batch';

        -- ... logic ...

        EXEC Logging.EndRun;
    END TRY
    BEGIN CATCH
        IF @@TRANCOUNT > 0 ROLLBACK;
        EXEC Logging.EndRun @Success = 0;
        THROW;
    END CATCH
END;

Error data now lands in the table in structured form. Inside the CATCH block, EndRun @Success = 0 writes the columns ErrorNumber, ErrorSeverity, ErrorState, ErrorLine and ErrorProcedure. A direct call to Logging.Error fills them too, in addition to the text in AdditionalInfo in the previous format.

On caller detection: T-SQL offers no query that returns the direct caller of a procedure. That leaves two ways: you pass @ProcId = @@PROCID, or you work with StartRun, in which case the stack already knows the procedure name. The run name may be at most 30 characters long so that Name + '_ABGESCHLOSSEN' fits into EventType NVARCHAR(50).

What you can query now

With run ID, duration and error number, three questions turn into simple queries that used to be guesswork.

Which runs are getting slower? The duration sits on the end entry, so a percentile query over the last seven days is enough:

SELECT DISTINCT
    ProcedureName,
    COUNT(*)              OVER (PARTITION BY ProcedureName) AS Runs,
    AVG(DurationMs)       OVER (PARTITION BY ProcedureName) AS AvgMs,
    MAX(DurationMs)       OVER (PARTITION BY ProcedureName) AS MaxMs,
    PERCENTILE_CONT(0.95) WITHIN GROUP (ORDER BY DurationMs)
                          OVER (PARTITION BY ProcedureName) AS P95Ms
FROM Logging.EventLog
WHERE EventType LIKE '%[_]ABGESCHLOSSEN'
  AND DurationMs IS NOT NULL
  AND EventTime >= DATEADD(DAY, -7, GETDATE())
ORDER BY MaxMs DESC;

Which runs never ended? A start without an end for the same RunID, older than five minutes, is a hanging or aborted run:

SELECT s.RunID, s.ProcedureName, s.EventTime AS StartTime
FROM Logging.EventLog s
WHERE s.EventType LIKE '%[_]START'
  AND s.RunID IS NOT NULL
  AND s.EventTime < DATEADD(MINUTE, -5, GETDATE())
  AND NOT EXISTS (SELECT 1 FROM Logging.EventLog e
                  WHERE e.RunID = s.RunID
                    AND (e.EventType LIKE '%[_]ABGESCHLOSSEN' OR e.EventType LIKE '%[_]FEHLER'))
ORDER BY s.EventTime;

Which errors actually occur? Group by stable attributes instead of message text:

SELECT TOP (20)
    ProcedureName, ErrorNumber, ErrorProcedure, ErrorLine,
    COUNT(*) AS Occurrences, MAX(EventTime) AS LastSeen
FROM Logging.EventLog
WHERE Severity = 'ERROR' AND ErrorNumber IS NOT NULL
GROUP BY ProcedureName, ErrorNumber, ErrorProcedure, ErrorLine
ORDER BY Occurrences DESC;

A hash of the message as a grouping key helps little as soon as the text contains variable parts. For entries without an error number, the only remedy is a convention: write a fixed text into Message and put everything variable into AdditionalInfo.

The rollback problem

A log entry written in the same transaction as the work disappears on ROLLBACK, which is exactly when you need it most. SQL Server has no autonomous transactions, so an ordinary INSERT into the log cannot be protected from that.

My way around it is a table variable, because it is not affected by ROLLBACK. The procedure collects its entries in a variable of type Logging.LogBuffer and writes them to the table with Logging.FlushBuffer after COMMIT or ROLLBACK, with the original time and in the original order:

DECLARE @Buf Logging.LogBuffer;

EXEC Logging.StartRun @Name = N'IMPORT', @ProcId = @@PROCID;

BEGIN TRY
    BEGIN TRAN;

    INSERT @Buf (EventType, Message) VALUES (N'IMPORT_DETAIL', N'Starting bulk update');
    -- ... work ...

    COMMIT;
    EXEC Logging.FlushBuffer @Buf;    -- flush first ...
    EXEC Logging.EndRun;              -- ... then end the run
END TRY
BEGIN CATCH
    IF @@TRANCOUNT > 0 ROLLBACK;      -- 1. roll back
    EXEC Logging.FlushBuffer @Buf;    -- 2. save the buffer
    EXEC Logging.EndRun @Success = 0; -- 3. error columns and duration
    THROW;
END CATCH

The order matters: flush first, then EndRun, otherwise the buffered entries lose their RunID because the run has already been popped from the stack.

The limits of the buffer

• It only covers the procedure that owns it. A called procedure cannot write into its caller's buffer because table-valued parameters are READONLY. Its ordinary Logging.Info calls are still lost on an outer ROLLBACK.
• It protects against ROLLBACK, not against aborts. On KILL, a dropped connection or a client timeout, the CATCH block does not run and the buffer is gone. The safety net in the next section covers that.

The safety net: Extended Events

A table logger only sees what ends up in a TRY/CATCH and is not rolled back. An Extended Events session on error_reported sees every error in the database, even without TRY/CATCH and independent of transactions. It complements the logger, it does not replace it.

The setup creates one session per database, named Logging_Errors_<DB>. At its core is a filter on severity and database ID, with a rolling file as the target:

ADD EVENT sqlserver.error_reported
(
    ACTION (sqlserver.database_name, sqlserver.client_app_name, sqlserver.client_hostname,
            sqlserver.username, sqlserver.session_id, sqlserver.sql_text)
    WHERE ([severity] >= 11 AND [sqlserver].[database_id] = <DB-ID>)
)
ADD TARGET package0.event_file (SET filename = N'...', max_file_size = (50), max_rollover_files = (4))

Logging.ImportXeErrors reads the .xel files incrementally into the table Logging.XeError, deduplicated by file name and offset. An Agent job should do this every few minutes, because the files roll over and older errors would otherwise disappear.

The interesting part is the field is_intercepted: it tells you whether a TRY/CATCH caught the error. That gives two reports. First, errors that reached the client uncaught (IsIntercepted = 0). Second, caught errors without a matching entry in the logger, compared by ErrorNumber within a window of ±5 seconds. Those are CATCH blocks that swallow the error instead of logging it. An error re-thrown with THROW can show up twice.

Two things you should know

• Privacy: The sql_text action can contain literals and parameter values with personal data. The setup lets you switch it off with a variable, and Logging.Cleanup deletes imported errors after 30 days by default.
• Permissions: Creating the session requires the server-level permission ALTER ANY EVENT SESSION, and reading the files requires VIEW SERVER STATE (from SQL Server 2022 on, VIEW SERVER PERFORMANCE STATE). If the permission is missing, the setup skips only this step and warns.

Installation and migration in one script

Everything lives in a single, idempotent script, Logging_Setup.sql, which you run in full in the application database. It detects the state of the database on its own and records it, with version and timestamp, in Logging.SetupHistory. Existing data is kept on every run.

The configuration is six variables at the very top of the script: migration yes or no, XE session yes or no, directory, file size and number of .xel files, and whether sql_text is captured. A pre-check requires SQL Server 2016 and compatibility level 130 or higher; otherwise the script aborts without changing anything.

The migration from the Logger schema is deliberately opt-in because it intervenes. It moves the table with ALTER SCHEMA TRANSFER, drops the five old procedures LogEvent, Debug, Info, Warn and Error, and creates synonyms for Logging.* in their place so that existing calls keep working. Back up your own customizations with sp_helptext first. If both tables exist, the script does not migrate, because I consider an automatic merge too risky.

There is also Logging.Cleanup for retention. It deletes in batches: DEBUG entries after 14 days, everything else after 90, and imported XE errors after 30. The values are parameters. It is not scheduled automatically; for it and for Logging.ImportXeErrors you create Agent jobs (cleanup daily, import every five minutes).

What the framework cannot do

A table logger is meant for business-process events, not for everything you might want to record in a database. The main limits:

• The run stack is per session. It has room for a few dozen nested runs. A forgotten EndRun leaves the entry on the stack for the rest of the session, which is why EndRun belongs in the CATCH block too.
• The buffer only protects the procedure that owns it, and only against ROLLBACK, not against KILL or timeouts.
• There is no automatic detection of the direct caller. Either @ProcId = @@PROCID or StartRun, otherwise the entry ends up under (unbekannt) (German for "unknown").

For other jobs there are better tools:

• Tracking changes to data: temporal tables, Change Tracking, CDC or SQL Server Audit, depending on whether you need history, delta sync or compliance.
• Performance and runtimes at scale: Query Store and Extended Events, without code changes.
• Application and database together: if a .NET app calls the procedures, logging really belongs in the app, for example with Serilog and the MSSQL sink or with OpenTelemetry. You tie it to the SQL side through a correlation ID that the app sets with sp_set_session_context.

Conclusion and download

What started as a simple log has become a tool for properly analyzing runs, durations and errors, one that still delivers when a ROLLBACK hits or an error slips through uncaught. The real lesson was a different one, though: a review of your own code finds bugs you do not see while writing, such as a caller detection built on a DMV that does not exist.

You can find the setup script and the reporting queries here: https://github.com/gpiwonka/Logging. Feedback and bug reports are welcome. https://piwonka.cc/Tickets/Create