1

We have an ASP.NET website with lots of traffic that has run happily for years, when suddenly it has began to log IndexOutOfRangeException errors when reading some SqlDataReader values, as if our SQL stored procedures were missing a column name.

This was a lie, because the URL mentioned in the error log was working fine for me, and was a page I knew a few thousand people would also be hitting every hour; yet the error log only showed it happening 80 times in 5 hours.

Only ten stored procedures appeared to be at fault, so it wasn't errorring on every SQL operation. Just the same ten over and over. Mostly very simple stuff with just SELECT...WITH(NOLOCK) in them.

I wasted valuable time making sure the stored procedures were still working (some were unchanged in years) and they were clearly returning the column names correctly. I even tried a DROP/CREATE to make sure they were recompiled. In the end another developer reached for the 'turn it off and on again' solution, and recycled the App Pool in IIS.

This solved the issue for about ten hours, then it crept back again (again, for about 1% of our visitors), whereupon we restarted IIS, and had another half a day's peace. But how long till it comes back again?!

I will paste what the log says, in case it matters:

Event code: 3005 
Event message: An unhandled exception has occurred. 
Event time: 24/04/2018 21:45:45 
Event time (UTC): 24/04/2018 21:45:45 
Event ID: e79bdcb8491b4e38851bd63298afef62 
Event sequence: 35007 
Event occurrence: 1278 
Event detail code: 0 

Application information: 
    Application domain: /LM/W3SVC/8/ROOT-1-131690781812076632 
    Trust level: Full 
    Application Virtual Path: / 
    Application Path: F:\BLAH\Whatever\ 
    Machine name: MACHINEDB 

Process information: 
    Process ID: 17824 
    Process name: w3wp.exe 
    Account name: IIS APPPOOL\Whatever 

Exception information: 
    Exception type: IndexOutOfRangeException 
    Exception message: PhotoCaption
   at System.Data.ProviderBase.FieldNameLookup.GetOrdinal(String fieldName)
   at System.Data.SqlClient.SqlDataReader.GetOrdinal(String name)
   at System.Data.SqlClient.SqlDataReader.get_Item(String name)
   at Combined.article.DoPhotoStuff(Int32 ArticleID) in F:\stuff\Whatever\photo\view.aspx.vb:line 69
   at Combined.article.Page_Load(Object sender, EventArgs e) in F:\stuff\Whatever\photo\view.aspx.vb:line 34
   at System.Web.UI.Control.OnLoad(EventArgs e)
   at System.Web.UI.Control.LoadRecursive()
   at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)

Request information: 
    Request URL: http://www.mywebsite.com/photo/12345 
    Request path: /photo/12345
    User host address: 157.55.39.214 
    User:  
    Is authenticated: False 
    Authentication Type:  
    Thread account name: IIS APPPOOL\Whatever

The code in each case was something like the following:

Dim oRecordSet As SqlDataReader = oCommand.ExecuteReader()
oRecordSet.Read()
Blah = oRecordSet("PhotoCaption") 'this line errors

There were also smaller numbers of HttpException errors, which claimed that DataBinding: 'System.Data.DataRowView' does not contain a property with the name 'PhotoLocation' when executing a Repeater.DataBind() - again, the sort of error you expect to get when you refer to a column name that doesn't exist in a recordset. Except those <asp:Repeater> details and the stored proc were all working perfectly for the other 99% of viewers.

Magnus Smith
  • 5,895
  • 7
  • 43
  • 64
  • Looks like a connection is shared across threads: https://social.msdn.microsoft.com/Forums/en-US/74a5db87-c63f-4386-b317-e848dedb2cd9/sqldatareadergetordinal-fails-rarely-with-indexoutofrange?forum=adodotnetdataproviders – rene Apr 25 '18 at 08:29
  • related if not a duplicate: https://stackoverflow.com/questions/4734051/intermittent-system-indexoutofrangeexception-when-reading-a-field-from-idataread – rene Apr 25 '18 at 08:32
  • Thanks @rene. The other SO question appears to have the entire website crashing, whereas ours carries on OK. But it could be the same issue so I will look into both those links. – Magnus Smith Apr 25 '18 at 08:58
  • What is most odd is that this code has worked happily for years, until yesterday! – Magnus Smith Apr 25 '18 at 08:59
  • If it is related to a connection that is re-used (either from the pool or not) across threads a small change in timing of code (patch Tuesday maybe?) can reveal threading bugs that never surfaced earlier. – rene Apr 25 '18 at 09:18
  • 1
    Wow, you're good! That did happen! And I think we are suffering from the issue where SQL connection pooling is unreliable with the `Shared` keyword. I've got some thinking to do... – Magnus Smith Apr 25 '18 at 15:41

0 Answers0