How to log NHibernate SQL to ASP.NET Core loggers

Logging down SQL created by ORM is useful when debugging new features of application. SQL logging in NHibernate is a little bit tricky and not so straightforward as it is with Entity Framework Core. This blog post demonstrates how to log SQL created by NHibernate to ASP.NET Core logger using NHibernate interceptor.

NB! In this post I will extend some parts of code shown in my blog post NHibernate on ASP.NET Core. Although I copied some code from this post here I suggest you to take time Myand see my previous work.

Getting NHibernate to ASP.NET Core

I defined IMapperSession interface that follows semantics of DbContext from Entity Framework Core. It’s similar but more general. We can use it with NHibernate, Entity Framework Core, Dapper, etc.

public interface IMapperSession
{
    void BeginTransaction();
    Task Commit();
    Task Rollback();
    void CloseTransaction();
    Task Save(Book entity);
    Task Delete(Book entity);
 
    IQueryable<Book> Books { get; }
}

I also implemented this interface for NHibernate. Here’s my demo code that is short and not very fool-proof.

public class NHibernateMapperSession : IMapperSession
{
    private readonly ISession _session;
    private ITransaction _transaction;
 
    public NHibernateMapperSession(ISession session)
    {
        _session = session;
    }
 
    public IQueryable<Book> Books => _session.Query<Book>();
 
    public void BeginTransaction()
    {
        _transaction = _session.BeginTransaction();
    }
 
    public async Task Commit()
    {
        await _transaction.CommitAsync();
    }
 
    public async Task Rollback()
    {
        await _transaction.RollbackAsync();
    }
 
    public void CloseTransaction()
    {
        if(_transaction != null)
        {
            _transaction.Dispose();
            _transaction = null;
        }
    }
 
    public async Task Save(Book entity)
    {
        await _session.SaveOrUpdateAsync(entity);
    }
 
    public async Task Delete(Book entity)
    {
        await _session.DeleteAsync(entity);
    }
}

I also provided solution for adding NHibernate to services collection in application Startup class.

public void ConfigureServices(IServiceCollection services)
{
    var connStr = Configuration.GetConnectionString("DefaultConnection");
 
    services.AddNHibernate(connStr);
    services.AddControllersWithViews();
}

Not excellent but works! It would be more polite and perfect to use options approach for getting NHibernate settings from application configuration to AddNHibernate() extension method. I don’t focus in it here but leave it as a topic for one of my future posts about NHibernate.

Here is AddNHibernate() extension method from my previous post.

public static class NHibernateExtensions
{
    public static IServiceCollection AddNHibernate(this IServiceCollection services, string connectionString)
    {
        var mapper = new ModelMapper();
        mapper.AddMappings(typeof(NHibernateExtensions).Assembly.ExportedTypes);
        HbmMapping domainMapping = mapper.CompileMappingForAllExplicitlyAddedEntities();
 
        var configuration = new Configuration();
        configuration.DataBaseIntegration(c =>
        {
            c.Dialect<MsSql2012Dialect>();
            c.ConnectionString = connectionString;
            c.KeywordsAutoImport = Hbm2DDLKeyWords.AutoQuote;
            c.SchemaAction = SchemaAutoAction.Validate;
            c.LogFormattedSql = true;
        });
        configuration.AddMapping(domainMapping);
 
        var sessionFactory = configuration.BuildSessionFactory();
 
        services.AddSingleton(sessionFactory);
        services.AddScoped(factory => sessionFactory.OpenSession());
        services.AddScoped<IMapperSession, NHibernateMapperSession>();
 
        return services;
    }
}

There’s actually no SQL logging when this solution is used.

Logging SQL to debug window

NHibernate sessions may have interceptor that give us access to some internals of NHibernate query execution. Bad thing is there can be only one interceptor set for NHibernate session. If we have more things to do through interceptor then we have to add code to our existing interceptor. We can use custom interceptor to log SQL.

My previous blog post about SQL logging in NHibernate demonstrated simple SQL logging interceptor that logged SQL to debug window.

public class SqlDebugOutputInterceptor : EmptyInterceptor
{
    public override SqlString OnPrepareStatement(SqlString sql)
    {
        Debug.Write("NHibernate: ");
        Debug.WriteLine(sql);
 
        return base.OnPrepareStatement(sql);
    }
}

Although NHibernate has IInterceptor interface defined it’s better to use EmptyInterceptor as base class so we don’t have to implement methods we don’t need.

Logging SQL to ASP.NET Core logger

We can use logger interceptor above to log SQL also to ASP.NET Core logger. For this we have to extend interceptor a little bit. Interceptor needs instance of ASP.NET Core logger and we will provide it through dependency injection. I also rename this interceptor to SqlLoggingInterceptor. Here’s the code.

public class SqlLoggingInterceptor : EmptyInterceptor
{
    private readonly ILogger<IMapperSession> _logger;
 
    public SqlLoggingInterceptor(ILogger<IMapperSession> logger)
    {
        _logger = logger;
    }
 
    public override SqlString OnPrepareStatement(SqlString sql)
    {
        if (_logger != null)
        {
            _logger.LogDebug(sql.ToString());
        }
 
        return base.OnPrepareStatement(sql);
    }
}

In ConfigureServices() method of Startup class we can add our interceptor to dependency injection like shown here.

#if (DEBUG)
            services.AddScoped<IInterceptor, SqlLoggingInterceptor>();
#endif

If application is released then SQL queries will not be logged.

Now we have to use SqlLoggingInterceptor in AddNHibernate() extension method. We can use services collection when creating new ISession to get interceptor if it is available. Here is the dependencies block from AddNHibernate() extension method.

services.AddSingleton(sessionFactory);
services.AddScoped(serviceProvider => 
{
    var interceptor = serviceProvider.GetService<IInterceptor>();
 
    return sessionFactory.OpenSession()
                         .SessionWithOptions()
                         .Interceptor(interceptor)
                         .OpenSession();
});
services.AddScoped<IMapperSession, NHibernateMapperSession>();

All log providers that log debug level messages will get generated SQL when it is written to log by interceptor.

NB! This solution doesn’t work with stateless sessions as stateless sessions doesn’t support interceptors. For stateless sessions we need some other approach and I will cover this topic in near future here in this blog.

What to do with stateless sessions?

Stateless sessions in NHibernate are great for reading data but they don’t support interceptors. It’s possible to hook to underlying connection and monitor it but it means building up a custom solution that may turn to be complex one.

If you are in hurry then the easiest thing to do is to offer few bucks and use Azure Monitor/Application Insights service. It is able to monitor external dependencies automatically and one of those dependencies is SQL database. You can run your ASP.NET Core application on your dev box and see SQL logs in Azure Portal.

Wrapping up

Using custom interceptor to log SQL queries in NHibernate to ASP.NET Core logger is simple but a little bit limited. It works with ISession that is stateful but not with IStatelessSession that doesn’t have state and therefore doesn’t support interceptors. As long as stateful sessions are used the logging interceptor logs all SQL that NHibernate sends out. It doesn’t matter what querying API is used – is it ICriteria, QueryOver or LINQ – all SQL will be written to logs.