6

Resolved

SQL Exceptions being thrown causes Orchard to lock up

description

While trying to write data to a column in the database a SQL Exception occurred due to the content exceeding the specified column size. (string was longer than the column length of varchar(150))

This exception did not bubble back up into the code and thus caused TransactionScope issues and locked the site up. Eventually it crashed completely.

I observed this in Orchard 1.7.1 and 1.7.2.

2014-01-27 15:05:01,445 [8] NHibernate.Util.ADOExceptionReporter - String or binary data would be truncated.
The statement has been terminated.
2014-01-27 15:05:01,508 [8] 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: String or binary data would be truncated.
The statement has been terminated.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning()
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
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)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(DbAsyncResult result, String methodName, Boolean sendToPipe)
at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
at System.Data.SqlClient.SqlCommandSet.ExecuteNonQuery()
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\SqlClientBatchingBatcher.cs:line 87
--- End of inner exception stack trace ---
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\SqlClientBatchingBatcher.cs:line 98
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatchWithTiming(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\AbstractBatcher.cs:line 413
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatch() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\AbstractBatcher.cs:line 397
at NHibernate.Engine.ActionQueue.ExecuteActions() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Engine\ActionQueue.cs:line 171
at NHibernate.Event.Default.AbstractFlushingEventListener.PerformExecutions(IEventSource session) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Event\Default\AbstractFlushingEventListener.cs:line 241
2014-01-27 15:05:01,554 [8] Orchard.Data.SessionLocator - Error while disposing the transaction.
NHibernate.Exceptions.GenericADOException: could not execute batch command.[SQL: SQL not available] ---> System.Data.SqlClient.SqlException: String or binary data would be truncated.
The statement has been terminated.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning()
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
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)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(DbAsyncResult result, String methodName, Boolean sendToPipe)
at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
at System.Data.SqlClient.SqlCommandSet.ExecuteNonQuery()
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\SqlClientBatchingBatcher.cs:line 87
--- End of inner exception stack trace ---
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\SqlClientBatchingBatcher.cs:line 98
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatchWithTiming(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\AbstractBatcher.cs:line 413
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatch() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\AbstractBatcher.cs:line 397
at NHibernate.Engine.ActionQueue.ExecuteActions() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Engine\ActionQueue.cs:line 171
at NHibernate.Event.Default.AbstractFlushingEventListener.PerformExecutions(IEventSource session) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Event\Default\AbstractFlushingEventListener.cs:line 253
at NHibernate.Event.Default.DefaultFlushEventListener.OnFlush(FlushEvent event) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Event\Default\DefaultFlushEventListener.cs:line 20
at NHibernate.Impl.SessionImpl.Flush() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Impl\SessionImpl.cs:line 1507
at NHibernate.Transaction.AdoTransaction.Commit() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Transaction\AdoTransaction.cs:line 193
at Orchard.Data.SessionLocator.Dispose() in c:\web\TritonDigital_1.7.2\Triton Digital\src\Orchard\Data\SessionLocator.cs:line 84
2014-01-27 15:05:31,850 [31] NHibernate.AdoNet.AbstractBatcher - Could not execute query: SELECT this_.Id as Id837_4_, this_.Number as Number837_4_, this_.Published as Published837_4_, this_.Latest as Latest837_4_, this_.Data as Data837_4_, this_.ContentItemRecord_id as ContentI6_837_4_, contentite1_.Id as Id836_0_, contentite1_.Data as Data836_0_, contentite1_.ContentType_id as ContentT3_836_0_, widgetpart2_.Id as Id853_1_, widgetpart2_.Title as Title853_1_, widgetpart2_.Position as Position853_1_, widgetpart2_.Zone as Zone853_1_, widgetpart2_.RenderTitle as RenderTi5_853_1_, widgetpart2_.Name as Name853_1_, commonpart3_.Id as Id855_2_, commonpart3_.OwnerId as OwnerId855_2_, commonpart3_.CreatedUtc as CreatedUtc855_2_, commonpart3_.PublishedUtc as Publishe4_855_2_, commonpart3_.ModifiedUtc as Modified5_855_2_, commonpart3_.Container_id as Container6_855_2_, contenttyp8_.Id as Id838_3_, contenttyp8_.Name as Name838_3_ FROM Orchard_Framework_ContentItemVersionRecord this_ inner join Orchard_Framework_ContentItemRecord contentite1_ on this_.ContentItemRecord_id=contentite1_.Id inner join Orchard_Widgets_WidgetPartRecord widgetpart2_ on contentite1_.Id=widgetpart2_.Id inner join Common_CommonPartRecord commonpart3_ on contentite1_.Id=commonpart3_.Id left outer join Orchard_Framework_ContentTypeRecord contenttyp8_ on contentite1_.ContentType_id=contenttyp8_.Id WHERE commonpart3_.Container_id in (@p0, @p1, @p2, @p3) and this_.Published = @p4 System.Data.SqlClient.SqlException (0x80131904): Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning()
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
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)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
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) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\AbstractBatcher.cs:line 223
2014-01-27 15:05:31,850 [31] NHibernate.Util.ADOExceptionReporter - Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
2014-01-27 15:05:31,850 [31] NHibernate.Util.ADOExceptionReporter - Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
2014-01-27 15:05:31,850 [31] NHibernate.Util.ADOExceptionReporter - Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.

comments

BuzzKeith wrote Feb 25 at 4:13 PM

We have also had problems with this issue, which is also exposed by the Orchard.Users module out of the box as max-length of username,email and password are not validated.

As a test I have just downloaded a fresh copy of 1.7.2 and installed (using sqlexpress 2012) and enabled user registration. Entered a username over 255 characters on the registration form and submitted, this causes the same exception seen above and leaving subsequnet requests jsut timing out and bringing down the site.

2014-02-25 15:52:58,965 [10] 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: String or binary data would be truncated.
The statement has been terminated.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction)
at System.Data.SqlClient.SqlInternalConnection.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.SqlCommand.ExecuteBatchRPCCommand()
at System.Data.SqlClient.SqlCommandSet.ExecuteNonQuery()
at NHibernate.AdoNet.SqlClientSqlCommandSet.ExecuteNonQuery() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\SqlClientSqlCommandSet.cs:line 117
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\SqlClientBatchingBatcher.cs:line 75
--- End of inner exception stack trace ---
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\SqlClientBatchingBatcher.cs:line 89
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatchWithTiming(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\AbstractBatcher.cs:line 412
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatch() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\AbstractBatcher.cs:line 397
at NHibernate.Engine.ActionQueue.ExecuteActions(IList list) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Engine\ActionQueue.cs:line 129
at NHibernate.Engine.ActionQueue.ExecuteActions() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Engine\ActionQueue.cs:line 169
at NHibernate.Event.Default.AbstractFlushingEventListener.PerformExecutions(IEventSource session) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Event\Default\AbstractFlushingEventListener.cs:line 241
2014-02-25 15:52:58,996 [10] Orchard.Data.SessionLocator - Error while disposing the transaction.
NHibernate.Exceptions.GenericADOException: could not execute batch command.[SQL: SQL not available] ---> System.Data.SqlClient.SqlException: String or binary data would be truncated.
The statement has been terminated.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction)
at System.Data.SqlClient.SqlInternalConnection.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.SqlCommand.ExecuteBatchRPCCommand()
at System.Data.SqlClient.SqlCommandSet.ExecuteNonQuery()
at NHibernate.AdoNet.SqlClientSqlCommandSet.ExecuteNonQuery() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\SqlClientSqlCommandSet.cs:line 117
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\SqlClientBatchingBatcher.cs:line 75
--- End of inner exception stack trace ---
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\SqlClientBatchingBatcher.cs:line 89
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatchWithTiming(IDbCommand ps) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\AbstractBatcher.cs:line 412
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatch() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\AdoNet\AbstractBatcher.cs:line 397
at NHibernate.Engine.ActionQueue.ExecuteActions(IList list) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Engine\ActionQueue.cs:line 129
at NHibernate.Engine.ActionQueue.ExecuteActions() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Engine\ActionQueue.cs:line 169
at NHibernate.Event.Default.AbstractFlushingEventListener.PerformExecutions(IEventSource session) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Event\Default\AbstractFlushingEventListener.cs:line 249
at NHibernate.Event.Default.DefaultFlushEventListener.OnFlush(FlushEvent event) in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Event\Default\DefaultFlushEventListener.cs:line 19
at NHibernate.Impl.SessionImpl.Flush() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Impl\SessionImpl.cs:line 1509
at NHibernate.Transaction.AdoTransaction.Commit() in c:\Users\sebros\Documents\My Projects\nhibernate-core\src\NHibernate\Transaction\AdoTransaction.cs:line 190
at Orchard.Data.SessionLocator.Dispose() in e:\Projects 2012\Orchard Master\Orchard.Source.1.7.2\src\Orchard\Data\SessionLocator.cs:line 84

Piedone wrote Feb 25 at 9:45 PM

This sounds like a huge exploit.

r3butler wrote Mar 9 at 11:19 PM

So, what is the solution?
I have a site that was running just fine on 1.7.2.
Both local and on Godaddy web hosting account.
Now if I log in and go to the Dashboard, make no changes but click any Publish Now button, I get this error.
I cannot make any edits anymore.

Ralph

sebastienros wrote Mar 18 at 8:46 PM

Can someone provide a simple repro ?

BuzzKeith wrote Mar 19 at 10:03 AM

The following steps on a fresh 1.7.2 install should do it:
As a test I have just downloaded a fresh copy of 1.7.2 and installed (using sqlexpress 2012) and enabled user registration. Entered a username over 255 characters on the registration form and submitted, this causes the same exception seen above and leaving subsequnet requests jsut timing out and bringing down the site.

sebastienros wrote Mar 20 at 11:27 PM

I can't repro it anymore in 1.7.x so I am marking it as resolved. But I can see the exception in the log, just that the database is not locked. To prevent it I have added some validation logic on the form.

arock3 wrote Mar 21 at 12:37 AM

To be clear on this issue, it wasn't from one of the forms baked into Orchard. I had built a custom module and was saving a contact form field to the database and I was entering a string longer than 150 chars to a 150 char field. The SQL exception was logged, but then it caused Orchard to lock up after. The exception should bubble up and not lock the site up.

also I should have validation on length, but even so...it shouldn't crash the site.

BuzzKeith wrote Apr 15 at 10:17 AM

Thanks Sebastien. I also have tested again this time against 1.7.3, taking the validation off the user registration and registering with a username over 255 charaters, sql truncation error no longer locks the database. The error is logged but fails silently.

Arock3 - whilst the test case I gave was on a core module this was simply to demonstrate the same error that you were experiencing which would not be specific to any module as it was more low level than that.