I have an ASP.NET MVC app featuring nHibernate as ORM (using SQL Server as database).
Every 5-6 requests, an exception is thrown containing random error described with the title above.
This is only happening on GET requests and starts with:
ERROR While preparing SELECT ..
These issues started ever since I've upgraded NHibernate 4.x to NHibernate 5.0.3 (5.1.1 now). During this process I've also updated the target framework, used to be .NET 4.5.2 now is .NET 4.7.2.
I've checked literally everything, made sure there aren't any connection leaks or timeouts against the DB but the error still persists. Tried switching the "TransparentNetworkIPResolution" and "Enlist" features off from the connection string - the problem is still here.
Any idea regarding the solution of the problem would be more than welcome.
This is the line that is the culprit for the exception below (DepartmentService:838):
var department = _departmentRepository.Get(departmentId);
The scenario is the following, I have multiple grids thus multiple requests are fired towards the same action. Every 5th-6th refresh of the same page, one of the many requests would fail (the one request that fails is random, i.e. sometimes it's the 1st, sometimes the 2nd, and so on).
Here is full exception snippet from my logs:
2020-06-26 13:25:16,297 [50] ERROR NHibernate.Util.ADOExceptionReporter [(null)] - While preparing SELECT department0_.DepartmentId as departmentid1_22_0_, department0_.CreatedAt as createdat4_22_0_, department0_.ModifiedAt as modifiedat5_22_0_, department0_.Name as name2_22_0_, department0_.Status as status6_22_0_, department0_.CreatedBy as createdby7_22_0_, department0_.ModifiedBy as modifiedby8_22_0_, department0_.SiteId as siteid3_22_0_ FROM dbo.Departments department0_ WHERE department0_.DepartmentId=@p0 an error occurred 2020-06-26 13:25:16,298 [50] ERROR NHibernate.Util.ADOExceptionReporter [(null)] - The requested operation cannot be completed because the connection has been broken.
2020-06-26 13:25:16,300 [50] ERROR [(null)] - NHibernate.ADOException: While preparing SELECT department0_.DepartmentId as departmentid1_22_0_, department0_.CreatedAt as createdat4_22_0_, department0_.ModifiedAt as modifiedat5_22_0_, department0_.Name as name2_22_0_, department0_.Status as status6_22_0_, department0_.CreatedBy as createdby7_22_0_, department0_.ModifiedBy as modifiedby8_22_0_, department0_.SiteId as siteid3_22_0_ FROM dbo.Departments department0_ WHERE department0_.DepartmentId=@p0 an error occurred ---> System.InvalidOperationException: The requested operation cannot be completed because the connection has been broken.
at System.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransaction(TransactionRequest transactionRequest, String name, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
at System.Data.SqlClient.SqlDelegatedTransaction.Initialize()
at System.Transactions.TransactionStatePSPEOperation.PSPEInitialize(InternalTransaction tx, IPromotableSinglePhaseNotification promotableSinglePhaseNotification, Guid promoterType)
at System.Transactions.TransactionStateActive.EnlistPromotableSinglePhase(InternalTransaction tx, IPromotableSinglePhaseNotification promotableSinglePhaseNotification, Transaction atomicTransaction, Guid promoterType)
at System.Transactions.Transaction.EnlistPromotableSinglePhase(IPromotableSinglePhaseNotification promotableSinglePhaseNotification, Guid promoterType)
at System.Transactions.Transaction.EnlistPromotableSinglePhase(IPromotableSinglePhaseNotification promotableSinglePhaseNotification)
at System.Data.SqlClient.SqlInternalConnection.EnlistNonNull(Transaction tx)
at System.Data.SqlClient.SqlInternalConnection.Enlist(Transaction tx)
at System.Data.ProviderBase.DbConnectionInternal.ActivateConnection(Transaction transaction)
at System.Data.ProviderBase.DbConnectionPool.PrepareConnection(DbConnection owningObject, DbConnectionInternal obj, Transaction transaction)
at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection)
at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, TaskCompletionSource1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection) at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)
at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource1 retry, DbConnectionOptions userOptions) at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource1 retry)
at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)
at System.Data.SqlClient.SqlConnection.Open()
at NHibernate.Connection.DriverConnectionProvider.GetConnection()
at NHibernate.AdoNet.ConnectionManager.GetConnection()
at NHibernate.AdoNet.AbstractBatcher.Prepare(DbCommand cmd)
--- End of inner exception stack trace ---at NHibernate.AdoNet.AbstractBatcher.Prepare(DbCommand cmd)
at NHibernate.AdoNet.AbstractBatcher.ExecuteReader(DbCommand cmd)
at NHibernate.Loader.Loader.GetResultSet(DbCommand st, QueryParameters queryParameters, ISessionImplementor session, IResultTransformer forcedResultTransformer)
at NHibernate.Loader.Loader.DoQuery(ISessionImplementor session, QueryParameters queryParameters, Boolean returnProxies, IResultTransformer forcedResultTransformer)
at NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(ISessionImplementor session, QueryParameters queryParameters, Boolean returnProxies, IResultTransformer forcedResultTransformer) at NHibernate.Loader.Loader.LoadEntity(ISessionImplementor session, Object id, IType identifierType, Object optionalObject, String optionalEntityName, Object optionalIdentifier, IEntityPersister persister) at NHibernate.Loader.Entity.AbstractEntityLoader.Load(ISessionImplementor session, Object id, Object optionalObject, Object optionalId) at NHibernate.Loader.Entity.AbstractEntityLoader.Load(Object id, Object optionalObject, ISessionImplementor session) at NHibernate.Persister.Entity.AbstractEntityPersister.Load(Object id, Object optionalObject, LockMode lockMode, ISessionImplementor session) at NHibernate.Event.Default.DefaultLoadEventListener.LoadFromDatasource(LoadEvent event, IEntityPersister persister, EntityKey keyToLoad, LoadType options) at NHibernate.Event.Default.DefaultLoadEventListener.DoLoad(LoadEvent event, IEntityPersister persister, EntityKey keyToLoad, LoadType options) at NHibernate.Event.Default.DefaultLoadEventListener.Load(LoadEvent event, IEntityPersister persister, EntityKey keyToLoad, LoadType options) at NHibernate.Event.Default.DefaultLoadEventListener.ProxyOrLoad(LoadEvent event, IEntityPersister persister, EntityKey keyToLoad, LoadType options) at NHibernate.Event.Default.DefaultLoadEventListener.OnLoad(LoadEvent event, LoadType loadType) at NHibernate.Impl.SessionImpl.FireLoad(LoadEvent event, LoadType loadType) at NHibernate.Impl.SessionImpl.Get(String entityName, Object id) at NHibernate.Impl.SessionImpl.Get[T](Object id) at Codera.Data.NHibernate.NHRepository1.Get(Object id) at Castle.Proxies.Invocations.NHRepository1_Get_10.InvokeMethodOnTarget() at Castle.DynamicProxy.AbstractInvocation.Proceed() at ISOQuest.Data.NHibernate.Interceptors.MethodInterceptor.Intercept(IInvocation invocation) in C:\Projects\ISOQuestGen6\ISOQuest.Data.NHibernate\Interceptors\MethodInterceptor.cs:line 49 at Castle.DynamicProxy.AbstractInvocation.Proceed() at Castle.Proxies.DepartmentRepositoryProxy.Get(Object id) at ISOQuest.Business.Services.DepartmentService.GetDepartmentAdministrators(Guid departmentId, Int32 type) in C:\Projects\ISOQuestGen6\Modules\ISOQuest\ISOQuest.Business\Services\Department\DepartmentService.cs:line 838 at ISOQuest.Web.Controllers.Api.DepartmentsController.LoadDepartmentAdministrators(Guid departmentId, Int32 type) in C:\Projects\ISOQuestGen6\Modules\ISOQuest\ISOQuest.Web\Controllers\Api\DepartmentsController.cs:line 454 at lambda_method(Closure , ControllerBase , Object[] ) at System.Web.Mvc.ReflectedActionDescriptor.Execute(ControllerContext controllerContext, IDictionary2 parameters) at System.Web.Mvc.ControllerActionInvoker.InvokeActionMethod(ControllerContext controllerContext, ActionDescriptor actionDescriptor, IDictionary2 parameters) at System.Web.Mvc.Async.AsyncControllerActionInvoker.b__39(IAsyncResult asyncResult, ActionInvocation innerInvokeState) at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult2.CallEndDelegate(IAsyncResult asyncResult) at System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeActionMethod(IAsyncResult asyncResult) at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3d() at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass46.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3f() at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass46.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3f() at System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeActionMethodWithFilters(IAsyncResult asyncResult) at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<>c__DisplayClass2b.<BeginInvokeAction>b__1c() at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<BeginInvokeAction>b__1e(IAsyncResult asyncResult) at System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeAction(IAsyncResult asyncResult) at System.Web.Mvc.Controller.<BeginExecuteCore>b__1d(IAsyncResult asyncResult, ExecuteCoreState innerState) at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid1.CallEndDelegate(IAsyncResult asyncResult) at System.Web.Mvc.Controller.EndExecuteCore(IAsyncResult asyncResult) at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid1.CallEndDelegate(IAsyncResult asyncResult) at System.Web.Mvc.Controller.EndExecute(IAsyncResult asyncResult) at System.Web.Mvc.MvcHandler.<BeginProcessRequest>b__5(IAsyncResult asyncResult, ProcessRequestState innerState) at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid1.CallEndDelegate(IAsyncResult asyncResult) at System.Web.Mvc.MvcHandler.EndProcessRequest(IAsyncResult asyncResult) at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() at System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step) at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)
After trying everything, I circled back to nHibernate 5.X change logs, ended up here: https://nhibernate.info/doc/nhibernate-reference/transactions.html, and found this little note at the very end of the changelog:
As of NHibernate v5.0, FlushMode.Commit requires the configuration setting transaction.use_connection_on_system_prepare to be true for flushing from transaction scope commit. Otherwise, it will be your responsibility to flush the session before completing the scope.Using transaction.use_connection_on_system_prepare can cause undesired transaction promotions to distributed: it requires using a dedicated connection for flushing, and it delays session disposal (if done inside the scope) to the scope disposal. If you want to avoid this, set this setting to false and manually flush your sessions.
For new applications, it is recommended to set transaction.use_connection_on_system_prepare to false, and to flush explicitly your sessions before scope completion. For old applications, consider checking how sessions are flushed, and if possible switch it to false too.
Basically, the one setting we had changed while migrating to nHibernate 5 was the FlushMode from "Auto" to "Commit", but somehow missed this flag (transaction.use_connection_on_system_prepare = false).
Hope this will help other people with legacy systems trying to upgrade!