Magic string causes error in nHibernate Profiler

Question

I've got a business application that I'm responsible for maintaining and this intermittent error keeps popping up regarding creating new comments in it. I finally got an exact string that causes it and after slowly narrowing down the paragraph of text to the exact portion causing it, I've narrowed it down the most base components. But I have no fix for it short of applying band-aids everywhere. I wanted to see if it's a common issue and possible get some feedback on it.

I'm using Fluent nHibernate (1.3.0.773) and nHibernate (3.3.1.400), I've stripped down my mapping file too so be sure it's not the cuase this is as simple as I could get it and still reproduce the error (and have a functioning build). This is the resulting content for comments when using FluentMappings.ExportTo() to dump the configuration.

<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2">
  <class xmlns="urn:nhibernate-mapping-2.2" name="Core.Comment, Core, Version=5.0.4720.19853, Culture=neutral, PublicKeyToken=null" table="tblComments">
    <id name="CommentId" type="System.Guid, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089">
      <column name="CommentId" />
      <generator class="guid.comb" />
    </id>
    <property name="OwnerId" type="System.Guid, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089">
      <column name="OwnerId" />
    </property>
    <property name="Text" type="System.String, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089">
      <column name="Description" />
    </property>
  </class>
</hibernate-mapping>

So pretty simple, but if the text being submitted has in it an apostrophe, then the word update followed by a closing parenthesis, I get an ArgumentOutOfRangeException error when I try to commit the transaction.

The following strings cause the problem

• Lorem ipsum dolor sit amet, consectetur. (This doesn't update)
• Doesn't update either)
• 'update)

These do not cause the problem

• Lorem ipsum dolor sit amet, consectetur. (This does update)
• update)
• 'update
• 'updat)

Any insight you can give would be great.

UPDATE: I should mention, when I hooked up nHibernate Profiler to this there was no SQL generated related to inserting a new record. So I'm assuming it's from some sort of logic inside of nHibernate?

Stacktrace

[ArgumentOutOfRangeException: Index was out of range. Must be non-negative and less than the size of the collection.
Parameter name: index]
   System.ThrowHelper.ThrowArgumentOutOfRangeException() +72
   System.Collections.Generic.List`1.get_Item(Int32 index) +34
   NHibernate.AdoNet.Util.FormatProcess.CloseParen() +141
   NHibernate.AdoNet.Util.FormatProcess.Perform() +452
   NHibernate.AdoNet.Util.BasicFormatter.Format(String source) +67
   NHibernate.AdoNet.SqlClientBatchingBatcher.AddToBatch(IExpectation expectation) +310
   NHibernate.Persister.Entity.AbstractEntityPersister.Insert(Object id, Object[] fields, Boolean[] notNull, Int32 j, SqlCommandInfo sql, Object obj, ISessionImplementor session) +914
   NHibernate.Persister.Entity.AbstractEntityPersister.Insert(Object id, Object[] fields, Object obj, ISessionImplementor session) +341
   NHibernate.Action.EntityInsertAction.Execute() +371
   NHibernate.Engine.ActionQueue.Execute(IExecutable executable) +48
   NHibernate.Engine.ActionQueue.ExecuteActions(IList list) +128
   NHibernate.Engine.ActionQueue.ExecuteActions() +35
   NHibernate.Event.Default.AbstractFlushingEventListener.PerformExecutions(IEventSource session) +156
   NHibernate.Event.Default.DefaultFlushEventListener.OnFlush(FlushEvent event) +180
   NHibernate.Impl.SessionImpl.Flush() +295
   NHibernate.Transaction.AdoTransaction.Commit() +189
   Web.Filters.NHibernateActionFilter.OnActionExecuted(ActionExecutedContext filterContext) in c:\Development\[Project Folder]\Web.Controllers\Filters\NHibernateActionFilter.cs:82
   System.Web.Mvc.Async.<>c__DisplayClass4f.<InvokeActionMethodFilterAsynchronously>b__49() +354
   System.Web.Mvc.Async.<>c__DisplayClass4f.<InvokeActionMethodFilterAsynchronously>b__49() +323
   System.Web.Mvc.Async.<>c__DisplayClass4f.<InvokeActionMethodFilterAsynchronously>b__49() +323
   System.Web.Mvc.Async.<>c__DisplayClass37.<BeginInvokeActionMethodWithFilters>b__36(IAsyncResult asyncResult) +44
   System.Web.Mvc.Async.WrappedAsyncResult`1.End() +139
   System.Web.Mvc.Async.AsyncResultWrapper.End(IAsyncResult asyncResult, Object tag) +102
   System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeActionMethodWithFilters(IAsyncResult asyncResult) +74
   System.Web.Mvc.Async.<>c__DisplayClass2a.<BeginInvokeAction>b__20() +68
   System.Web.Mvc.Async.<>c__DisplayClass25.<BeginInvokeAction>b__22(IAsyncResult asyncResult) +184
   System.Web.Mvc.Async.WrappedAsyncResult`1.End() +136
   System.Web.Mvc.Async.AsyncResultWrapper.End(IAsyncResult asyncResult, Object tag) +56
   System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeAction(IAsyncResult asyncResult) +66
   System.Web.Mvc.<>c__DisplayClass1d.<BeginExecuteCore>b__18(IAsyncResult asyncResult) +40
   System.Web.Mvc.Async.<>c__DisplayClass4.<MakeVoidDelegate>b__3(IAsyncResult ar) +47
   System.Web.Mvc.Async.WrappedAsyncResult`1.End() +151
   System.Web.Mvc.Async.AsyncResultWrapper.End(IAsyncResult asyncResult, Object tag) +59
   System.Web.Mvc.Async.AsyncResultWrapper.End(IAsyncResult asyncResult, Object tag) +40
   System.Web.Mvc.Controller.EndExecuteCore(IAsyncResult asyncResult) +68
   System.Web.Mvc.Async.<>c__DisplayClass4.<MakeVoidDelegate>b__3(IAsyncResult ar) +47
   System.Web.Mvc.Async.WrappedAsyncResult`1.End() +151
   System.Web.Mvc.Async.AsyncResultWrapper.End(IAsyncResult asyncResult, Object tag) +59
   System.Web.Mvc.Async.AsyncResultWrapper.End(IAsyncResult asyncResult, Object tag) +40
   System.Web.Mvc.Controller.EndExecute(IAsyncResult asyncResult) +65
   System.Web.Mvc.Controller.System.Web.Mvc.Async.IAsyncController.EndExecute(IAsyncResult asyncResult) +39
   System.Web.Mvc.<>c__DisplayClass8.<BeginProcessRequest>b__3(IAsyncResult asyncResult) +45
   System.Web.Mvc.Async.<>c__DisplayClass4.<MakeVoidDelegate>b__3(IAsyncResult ar) +47
   System.Web.Mvc.Async.WrappedAsyncResult`1.End() +151
   System.Web.Mvc.Async.AsyncResultWrapper.End(IAsyncResult asyncResult, Object tag) +59
   System.Web.Mvc.Async.AsyncResultWrapper.End(IAsyncResult asyncResult, Object tag) +40
   System.Web.Mvc.MvcHandler.EndProcessRequest(IAsyncResult asyncResult) +66
   System.Web.Mvc.MvcHandler.System.Web.IHttpAsyncHandler.EndProcessRequest(IAsyncResult result) +38
   System.Web.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() +9629708
   System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously) +155

Answer 1

Ok, so I found out what was causing it. As soon as I removed nHibernate Profiler's initialization from my project the error stopped occurring. It must have been trying to format the string for logging prior to executing it - and because it blew up, it never got to actually executing the query. Which to me wrong, logging should swallow errors, or at the very least not let it interfere with normal operations.

Update: Same problem occurs when nHibernate Profiler 2 is used, but as soon as I comment out NHibernateProfiler.Initialize(), the issue goes away. Going to see if I can get some support from the developer. Note that you actually don't have to be attached your process using nHibernate Profiler, simply having the profiler initialized is enough to cause the problem. I have attempted to contact nHibernate Profiler support via email on Dec 5th and have not heard anything back yet, so I don't know if this has been looked at yet or not.

Answer 2

As this is one of the top questions that popup when I search online with exact error message, I thought it would be helpful for people to know how I fixed it.

The error stack trace mentioned in the question is actually thrown by NHibernate's BasicFormatter. There is a documented issue for this error on NHibernate's GitHub repository. Here is the link - https://github.com/nhibernate/nhibernate-core/issues/1319.

The error has been fixed in latest NHibernate at the time of writing this answer. For older versions such as 3.1.0 (the version I was working with when facing the error), setting format_sql property to false in nhibernate.config file fixes the issue.