Tuesday, 10 June 2025

Database logging Entity Framework queries to SeriLog

Logging database queries from Entity Framework can be done using Sql Server Profiler or using Profiling tools inside VS 2022. A problem with this approach is that Sql server profiler tends to log very much other events than just the queries to the database and if you use the Profiling tool, they will truncate large queries. Note that database logging the traffic will quickly grow into large logs, of several gigabyte. Database logging can also reveal sensitive data, another challenge. But having a tailored database log can for developers be a helpful tool to both profile and check queries, especially when using an ORM like Entity Framework that can hide the actual queries being sent to the database since that part is abstracted away via IQueryable. Once you have the queries you want to inspect, you can profile them inside SQL Server Management Studio and check if the use of indexes in database are optimal or if more indexes should be added. In case you as a developer want to inspect queries that your application does, maybe activated via an app setting in config, you might be better off with a tailored way of logging the database queries that the application performs. This article will look at Entity Framework 6 for .NET Framework and Db interceptor that logs compacted, one-lined, interpolated queries that Entity Framework runs. Note that also later version of Entity Framework support db interceptors, such as EF Core 8 (for .NET 8). Let's first look at the repo for the code of this article :

https://github.com/toreaurstadboss/BulkOperationsEntityFramework

SerilogCommandInterceptor

The db interceptor looks like this, it will log to a file that uses SeriLog as a logging framework and to format the logging file(s).


using Serilog;
using System;
using System.Configuration;
using System.Data.Common;
using System.Data.Entity.Infrastructure.Interception;

namespace BulkOperationsEntityFramework.Test
{

    /// <summary>
    /// Intercepts Entity Framework database commands and logs them using Serilog.
    /// 
    /// This interceptor captures and logs SQL command text for NonQuery, Reader, and Scalar operations.
    /// Logging is configured via Serilog and can be customized using <c>App.config</c> or <c>Web.config</c> settings.
    /// 
    /// <para>
    /// <b>Configuration via AppSettings:</b>
    /// </para>
    /// <list type="table">
    ///   <item>
    ///     <term>serilog:write-to:File.path</term>
    ///     <description>Path to the log file. Default: <c>databaselogs\log.txt</c></description>
    ///   </item>
    ///   <item>
    ///     <term>serilog:write-to:File.rollingInterval</term>
    ///     <description>Rolling interval for log files (e.g., <c>Day</c>, <c>Hour</c>). Default: <c>Day</c></description>
    ///   </item>
    ///   <item>
    ///     <term>serilog:minimum-level</term>
    ///     <description>Minimum log level (e.g., <c>Information</c>, <c>Warning</c>). Default: <c>Information</c></description>
    ///   </item>
    ///   <item>
    ///     <term>serilog:write-to:File.retainedFileCountLimit</term>
    ///     <description>Number of log files to retain. Default: <c>21</c></description>
    ///   </item>
    /// </list>
    /// 
    /// <para>
    /// <b>Example App.config override:</b>
    /// </para>
    /// <code language="xml">
    /// <appSettings>
    ///   <add key="serilog:write-to:File.path" value="C:\Logs\mydb.log" />
    ///   <add key="serilog:write-to:File.rollingInterval" value="Hour" />
    ///   <add key="serilog:minimum-level" value="Warning" />
    ///   <add key="serilog:write-to:File.retainedFileCountLimit" value="10" />
    /// </appSettings>
    /// </code>
    /// </summary>
    public class SerilogCommandInterceptor : IDbCommandInterceptor
    {

        private static bool _isInitialized = false;

        public SerilogCommandInterceptor()
        {
            if (_isInitialized)
            {
                return;
            }

            var logPath = ConfigurationManager.AppSettings["serilog:write-to:File.path"] ?? "databaselogs\\log.txt";
            var logIntervalRaw = ConfigurationManager.AppSettings["serilog:write-to:File.rollingInterval"];
            var logInterval = Enum.TryParse(logIntervalRaw, true, out RollingInterval interval) ? interval : RollingInterval.Day;
            var minLevelRaw = ConfigurationManager.AppSettings["serilog:minimum-level"];
            var logLevel = Enum.TryParse(minLevelRaw, true, out Serilog.Events.LogEventLevel level) ? level : Serilog.Events.LogEventLevel.Information;
            var retainedCountRaw = ConfigurationManager.AppSettings["serilog:write-to:File.retainedFileCountLimit"];
            var retainedCount = int.TryParse(retainedCountRaw, out int count) ? count : 21;

            //Set up Serilog logging for the database logging interceptor - set up the minimum level to Information and
            //write to a file with rolling intervals. Set up the file size limit to 500 MB per file
            //in case the log file grows too large on a given day, it will roll over to a new file with the with a running number suffixed to it 
            //the logs will be stored in the "databaselogs" subfolder, or configured path in config file
            //logs will be kept or a maximum number of 21 days or specified number of days
            Log.Logger = new LoggerConfiguration()
                .MinimumLevel.Is(logLevel)
                .WriteTo.File(
                    logPath, 
                    rollingInterval: logInterval, 
                    rollOnFileSizeLimit: true,
                    fileSizeLimitBytes: 500 * 1000 * 1000,
                    outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss} {Level:u3}] [SQL] {Message:lj}{NewLine}",
                    retainedFileCountLimit: retainedCount
                )
                .CreateLogger();

            _isInitialized = true;
        }

        public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext) { }

        public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext) =>
            Log.Information("{Tag} {Sql}", GetSqlTag(command.CommandText), CompactAndInterpolateSql(command));

        public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) { }

        public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) =>
            Log.Information("{Tag} {Sql}", GetSqlTag(command.CommandText), CompactAndInterpolateSql(command));

        public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext) { }

        public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext) =>
            Log.Information("{Tag} {Sql}", GetSqlTag(command.CommandText), CompactAndInterpolateSql(command));

        private string CompactAndInterpolateSql(DbCommand dbCommand)
        {
            string sql = InterpolateSql(dbCommand);
            return CompactSql(sql);
        }

        private string CompactSql(string sql) =>
            sql.Replace(Environment.NewLine, " ").Replace("\n", "").Replace("\r", " ").Trim();

        private string GetSqlTag(string sql)
        {
            if (sql.StartsWith("SELECT", StringComparison.OrdinalIgnoreCase)) return "[SELECT]";
            if (sql.StartsWith("INSERT", StringComparison.OrdinalIgnoreCase)) return "[INSERT]";
            if (sql.StartsWith("UPDATE", StringComparison.OrdinalIgnoreCase)) return "[UPDATE]";
            if (sql.StartsWith("DELETE", StringComparison.OrdinalIgnoreCase)) return "[DELETE]";
            return "[SQL]";
        }

        private string InterpolateSql(DbCommand dbCommand)
        {
            string sql = dbCommand.CommandText;
            foreach (DbParameter parameter in dbCommand.Parameters)
            {
                string value = FormatParameterValue(parameter.Value);
                sql = sql.Replace(parameter.ParameterName, value);
            }
            return sql;
        }

        private string FormatParameterValue(object value)
        { 
            if (value == null || value == DBNull.Value)
            {
                return "NULL";
            }
            if (value is string || value is DateTime || value is Guid)
            {
                return $"'{value}'"; // Wrap strings, DateTime, and Guid in single quotes
            }
            if (value is bool b)
            {
                return b ? "1" : "0";
            }

            return value.ToString();
        }        

    }
}


Adding a db interceptor should be preferably done once, for example in a static constructor, to ensure the db interceptor is available right away. Example of a simple db context that adds the interceptor shown above.


using BulkOperationsEntityFramework.Models;
using BulkOperationsEntityFramework.Test;
using System.ComponentModel.DataAnnotations.Schema;
using System.Data.Entity;
using System.Data.Entity.Infrastructure.Interception;

namespace BulkOperationsEntityFramework
{

    public class ApplicationDbContext : DbContext
    {

        static ApplicationDbContext()
        {
            DbInterception.Add(new SerilogCommandInterceptor());
        }

        public ApplicationDbContext() : base("name=App")
        {
        }

        public DbSet<User> Users { get; set; }

        protected override void OnModelCreating(DbModelBuilder modelBuilder)
        {
            modelBuilder.Entity<User>().HasKey(u => u.Id);
            modelBuilder.Entity<User>().Property(u => u.Id).HasDatabaseGeneratedOption(DatabaseGeneratedOption.Identity);
        }

    }

}




Since Serilog is used, a great flexibility to the logging is possible to do. For example, logging database queries can be done with rolling intervals, such as logging per hour or per day or even per minute for example. Also, a max size for logs can be set. The logging within the same time interval for the logging is split into multiple log files, when log files reaches size limit. Example app config settings are here:


<appSettings>
	<add key="serilog:write-to:File.path" value="logs\dblogv3.txt" />
	<add key="serilog:minimum-level" value="Information" />
	<add key="serilog:write-to:File.rollingInterval" value="Day" />
	<add key="serilog:file:retentionDays" value="21" />
</appSettings>


If you use a tool like TailBlazer, opening very large logs of many gigabytes is fairly fast and you can define highlighting rules to discern between different types of queries.
A screenshot of the highlighting rules of Tail Blazor for the previous screen shot shown is shown below:



Tail Blazer tool

The Tail Blazer tool can be downloaded from GitHub here:

https://github.com/RolandPheasant/TailBlazer
Share this article on LinkedIn.

No comments:

Post a Comment