6
Vote

NHibernates / Orchard doesn't handle correctly Violation of UNIQUE KEY constraint

description

If you have protected you DB with a UNIQUE KEY constraint on some record, when there is a try to save a duplicate key, it seems that NH session get no more synchronized with real DB and is behaving badly.
Seems that some bad image of content item continue to exist in NH memory and cash through the next Http requests, blocking Orchard. System become unresponsive for several minutes.
Very bad.
Orchard trying to execute a query on version and non existing part....

A sample of trace.
2013-06-25 11:49:11,256 [22] NHibernate.Util.ADOExceptionReporter - Violation of UNIQUE KEY constraint 'uc_pl_currency_prod'. Cannot insert duplicate key in object 'dbo.Datwendo_Commerce_ProductPriceListPartRecord'. The duplicate key value is (39, 26, 27).
The statement has been terminated.
2013-06-25 11:49:11,350 [22] NHibernate.Event.Default.AbstractFlushingEventListener - Could not synchronize database state with session
NHibernate.Exceptions.GenericADOException: could not execute batch command.[SQL: SQL not available] ---> System.Data.SqlClient.SqlException: Violation of UNIQUE KEY constraint 'uc_pl_currency_prod'. Cannot insert duplicate key in object 'dbo.Datwendo_Commerce_ProductPriceListPartRecord'. The duplicate key value is (39, 26, 27).
The statement has been terminated.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource
1 completion, Int32 timeout, Task& task, Boolean asyncWrite)
at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean asyncWrite)
at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
at System.Data.SqlClient.SqlCommandSet.ExecuteNonQuery()
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps)
--- End of inner exception stack trace ---
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps)
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatchWithTiming(IDbCommand ps)
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatch()
at NHibernate.Engine.ActionQueue.ExecuteActions()
at NHibernate.Event.Default.AbstractFlushingEventListener.PerformExecutions(IEventSource session)
2013-06-25 11:49:11,365 [22] Orchard.Data.SessionLocator - Error while disposing the transaction.
NHibernate.Exceptions.GenericADOException: could not execute batch command.[SQL: SQL not available] ---> System.Data.SqlClient.SqlException: Violation of UNIQUE KEY constraint 'uc_pl_currency_prod'. Cannot insert duplicate key in object 'dbo.Datwendo_Commerce_ProductPriceListPartRecord'. The duplicate key value is (39, 26, 27).
The statement has been terminated.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action
1 wrapCloseInAction)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean asyncWrite)
at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource
1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean asyncWrite)
at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
at System.Data.SqlClient.SqlCommandSet.ExecuteNonQuery()
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps)
--- End of inner exception stack trace ---
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps)
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatchWithTiming(IDbCommand ps)
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatch()
at NHibernate.Engine.ActionQueue.ExecuteActions()
at NHibernate.Event.Default.AbstractFlushingEventListener.PerformExecutions(IEventSource session)
at NHibernate.Event.Default.DefaultFlushEventListener.OnFlush(FlushEvent event)
at NHibernate.Impl.SessionImpl.Flush()
at NHibernate.Transaction.AdoTransaction.Commit()
at Orchard.Data.SessionLocator.Dispose()
2013-06-25 11:49:41,474 [6] NHibernate.AdoNet.AbstractBatcher - Could not execute query: SELECT this_.Id as Id48_3_, this_.Number as Number48_3_, this_.Published as Published48_3_, this_.Latest as Latest48_3_, this_.Data as Data48_3_, this_.ContentItemRecord_id as ContentI6_48_3_, contentite1_.Id as Id47_0_, contentite1_.Data as Data47_0_, contentite1_.ContentType_id as ContentT3_47_0_, productpri2_.Id as Id96_1_, productpri2_.DPrice as DPrice96_1_, productpri2_.DPublicPrice as DPublicP3_96_1_, productpri2_.DAcquisitionPrice as DAcquisi4_96_1_, productpri2_.DFixedAmount as DFixedAm5_96_1_, productpri2_.Percentage as Percentage96_1_, productpri2_.ComputeMode as ComputeM7_96_1_, productpri2_.Comments as Comments96_1_, productpri2_.Product_id as Product9_96_1_, productpri2_.PriceList_id as PriceList10_96_1_, productpri2_.Currency_id as Currency11_96_1_, contenttyp6_.Id as Id49_2_, contenttyp6_.Name as Name49_2_ FROM Orchard_Framework_ContentItemVersionRecord this_ inner join Orchard_Framework_ContentItemRecord contentite1_ on this_.ContentItemRecord_id=contentite1_.Id inner join Datwendo_Commerce_ProductPriceListPartRecord productpri2_ on contentite1_.Id=productpri2_.Id left outer join Orchard_Framework_ContentTypeRecord contenttyp6_ on contentite1_.ContentType_id=contenttyp6_.Id WHERE productpri2_.PriceList_id = @p0 and this_.Published = @p1 System.Data.SqlClient.SqlException (0x80131904): Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
at System.Data.SqlClient.SqlDataReader.get_MetaData()
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource
1 completion, Int32 timeout, Task& task, Boolean asyncWrite)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader()
at NHibernate.AdoNet.AbstractBatcher.ExecuteReader(IDbCommand cmd)
ClientConnectionId:013e7c7f-f662-424e-abe5-4c4ccb79a8bd
2013-06-25 11:49:41,474 [6] NHibernate.Util.ADOExceptionReporter - Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
2013-06-25 11:49:41,474 [6] NHibernate.Util.ADOExceptionReporter - The wait operation timed out
2013-06-25 11:49:41,474 [6] NHibernate.Util.ADOExceptionReporter - Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
2013-06-25 11:49:41,474 [6] NHibernate.Util.ADOExceptionReporter - The wait operation timed out
2013-06-25 11:49:41,474 [6] NHibernate.Util.ADOExceptionReporter - Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
2013-06-25 11:49:41,474 [6] NHibernate.Util.ADOExceptionReporter - The wait operation timed out
2013-06-25 11:49:41,474 [6] Orchard.Exceptions.DefaultExceptionPolicy - An unexpected exception was caught
NHibernate.Exceptions.GenericADOException: could not execute query
[ SELECT this_.Id as Id48_3_, this_.Number as Number48_3_, this_.Published as Published48_3

comments

sebastienros wrote Sep 24, 2013 at 9:05 PM

Is it a bug in NHibernate ?

CSADNT wrote Sep 24, 2013 at 11:28 PM

I still had no time to understand NHibernate (maybe because I find it prehistoric, certainly due to the hibernate part of the name).... but the session get totally broken and the cache (syscache ? and/or normal cahe corrupted by bad objectts )