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

Housefly

Can you post the entire error stack trace please? – Furore

Can we also see you update code? – Allogamy

There is no update code, it's using the built in nHibernate functionality. If you mean the resulting SQL there isn't any, at least according to nHibernate Profiler. It's failing before any SQL gets sent. – Housefly

sorry insert code, How are you inserting data? – Allogamy

essentially just this Session.Save(commentObject); It's using a Repository/Service/Controller model in MVC4 – Housefly

I was tempted to look at creating an ticket on the issue tracker for nHibernate but I wanted to check here first and see if it's something stupid I'm not seeing. – Housefly

What database are you using? Can you change the "Text" property to a different name in a test environment to see if that resolves the issue? – Cornelie

SQL 2008 R2 I believe. And I just changed the property on my object to be called Message instead and I get the same error when I try to save – Housefly

I'm creating a standalone MVC4 project with one controller and the model/bindings needed for just comments to see if I can narrow this down even further... – Housefly

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.

Housefly

Anyone know if there is a better way to get support for nHibernate Profiler issues? – Housefly

Hey, I requested you by mail to send us a sample project that reproduce this issue. – Landy

Yeah I saw that. I got it to reproduce the problem in a small project, but as soon as I switched my project from using Fluent nHibernate Mappings to Loquacious Mappings it went away, so now I'm trying to find out how to get nHibernate to export the HBM files when using Loquacious mapping so I can compare to what Fluent nHibernate's... – Housefly

We'll continue to discuss this by email. – Landy

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.

Findley