Intermittent database exceptions during Fetch operations
I am using Umbraco version 7.4.3 assembly: 1.0.5948.18141
I am getting intermittent exceptions during fetch operations. I have scoured the web for answers and am coming up empty. This is what shows up in my umbraco log file when I get these errors. I have validated that with the same query that works over and over again, that occasionally I get this error. I have added retry logic with garbage collection in the exception handlers and sleep statements, but to no avail. Anything anyone could suggest to shed light on this would be extremely helpful. I am desperate. :)
2016-11-03 10:49:12,240 [P2872/D6/T1120] ERROR Umbraco.Core.Persistence.UmbracoDatabase - Database exception occurred
System.NullReferenceException: Object reference not set to an instance of an object.
at Umbraco.Core.Persistence.Database.
Hey - A nullref exception in Database is a weird thing. In addition, it looks like the stack trace gets truncated in the log (ie contains only 1 line) - or is it you filtering the lines?
Could you post more of the log, including some context (what happens before and after)? And make sure it is properly formatted as your original post is garbled?
Also, can you give a bit of context about the query itself, where it runs (controller, view...)?
I am attaching a text file that contains some more background and details about what is going on. I did not trim the log entries, the entries in the Umbraco log except is the only exception information at the time of the error. I appreciate you looking into this, it has me scratching my head and my next step is probably going to upgrade to 7.5 to see if that helps, but that is a bigger task since I have to test it on my dev and qa environments before rolling it out to prod and that is a pretty big task.
Thank you!
Robert
Text File Contents:
Background:
I am using MySql version 5.7. There are NO Errors in the mySQL log from what I can tell mySql executes correctly.
I tried bypassing Petapoco all together and going directly to mySQL itself to no avail. Connecting and executing
readers myself just broke umbraco after that.
When this scenario is unfolding system resources are normal and
mySql is running will full efficiency, or so the dashboard and logs indicate. This error happens about 15% of the time
and this is a rough estimate. Sometimes I see it more often then not and sometimes I don't see it for hours of
high useage.
Originally I thought configuration changes were causing app pool shutdowns (which they were) and I resolved that by
modifying the web.config:
This resolved the multiple app pool shutdowns in the log, but did not resolve the issue below.
Details:
I have a controller that is derived from: Umbraco.Web.Mvc.RenderMvcController
In that controller I am making a call to a Modelobject. That loads an object based on a SQL statement.
This code is called everytime a user logs into the system as well as various times during the user experience.
The code that matches the exception you see below is what I am calling to fetch the results:
NOTE: The Retry code was a desperate attempt to work around the problem to no avail.
public static List<SchoolClubDB> LoadSchoolClubs(string strWhere)
{
List<SchoolClubDB> oRet = null;
int iRetryCount = 0;
while (oRet == null && iRetryCount <= 2)
{
try
{
//This is the line that generates the exception below
oRet = Umbraco.Core.ApplicationContext.Current.DatabaseContext.Database.Fetch<SchoolClubDB>("SELECT * FROM _schoolClubs " + strWhere + ";");
}
catch (Exception ex)
{
++iRetryCount;
CCCommon.Support.WriteErrorExceptionEvent(ex, "LoadSchoolClubs",strWhere );
CCCommon.Support.WriteInfoEvent("LoadSchoolClubs", "Retrying: " + iRetryCount.ToString());
System.GC.Collect();
System.Threading.Thread.Sleep(1000);
}
}
return oRet;
}
This exception is from my own logging that I generate in the exception handler above. It is a little
redundant since I dump a full stack trace after the initial one.
--------------------------- My Custom Log -----------------------------
2016-11-14 20:17:57.8443 Error: Browser: Safari IP: 24.98.214.237 HOST: 24.98.214.237 : LoadSchoolClubs: WHERE SchoolId=34
System.NullReferenceException: Object reference not set to an instance of an object.
at Umbraco.Core.Persistence.Database.
--------------------------------- End My Custom Log ------------------------------------
--------------------------------- Umbraco Log Entries that occur at same time -----------
System.NullReferenceException: Object reference not set to an instance of an object.
at Umbraco.Core.Persistence.Database.
------------------------------- End Umbraco Log ---------------------------------------
and the error is a null reference exception when iterating over the records that are being read. Considering that it works some of the time, and that "retrying" does not improve the situation... I'd be tempted to think about an issue with data.
What does the SchoolClubDB class look like, and is it possible that in some cases, what is returned by the database causes the class to fail to initialize properly?
Since I am not sure what the underlying problem is, I can't say for certain. What I can say, is the the query uses the primary key (id) to do the fetch. It is unique in the tables and there are only about 70 different rows in that table. The class itself is included for your edification.
The data itself for the various rows once configured is pretty static, and I would execute the same code myself when I see the entries in the logs, and the same ones would work. I.E. Where SchoolId=34, will throw the exception in the logs, but then again with the same schooldId and no underlying data change will work when I try it again. I am not sure if this answers your question, I would love to find this to be a coding issue because I could fix it. At the moment though I am unsure what is causing this.
Now, one thing I just changed to see what will happen based on your question, is I added a [ignore] decoration to the listSchoolClubs variable. I am not sure if that is even examined during the fetch or query, but figured it can't hurt since it is a variable intended to hold a subset of children items not related to a specific database entry.
Here is the class for the SchoolDB:
using System;
using System.Collections.Generic;
using System.Linq;
using System.Web;
using Umbraco.Core.Persistence;
using Umbraco.Core.Persistence.DatabaseAnnotations;
namespace ChampionshipChessUmbraco.Models
{
[TableName("_Schools")]
[PrimaryKey("id", autoIncrement = true)]
[ExplicitColumns]
public class SchoolDB : DBModule
{
public SchoolDB() : base()
{ }
public SchoolDB(school oData) : base(oData)
{ }
[Column("id")]
[PrimaryKeyColumn(AutoIncrement = true)]
public int id { get; set; }
[Column("AffilliateId")]
public int AffilliateId { get; set; }
[Column("SchoolName")]
public string SchoolName { get; set; }
[Column("Contact")]
public string Contact { get; set; }
[Column("Email")]
public string Email { get; set; }
[Column("Phone")]
public string Phone { get; set; }
[Column("StreetAddress")]
public string StreetAddress { get; set; }
[Column("City")]
public string City { get; set; }
[Column("County")]
public string County { get; set; }
[Column("State")]
public string State { get; set; }
[Column("Zip")]
public string Zip { get; set; }
[Column("Active")]
public bool Active { get; set; }
[Column("Private")]
public bool Private { get; set; }
[Column("Comments")]
public string Comments { get; set; }
[Column("Notes")]
public string Notes { get; set; }
public List<SchoolClubDB> listsSchoolClubs { get; set; }
public static List<SchoolDB> LoadSchools(string strState, string strCounty)
{
List<SchoolDB> oRet = null;
try
{
if (strCounty == "Private School")
{
oRet = Umbraco.Core.ApplicationContext.Current.DatabaseContext.Database.Fetch<SchoolDB>("SELECT * FROM _schools WHERE state='" + strState + "' AND Private=1 AND Active=1 ORDER BY SchoolName;");
}
else
{
//return db.Query<PostAJob>("SELECT * FROM job WHERE customerId=@0", memberId);
//listAffilliates = Umbraco.Core.ApplicationContext.Current.DatabaseContext.Database.Query<affilliate>("SELECT * FROM _affilliates;") as List<affilliate>;
oRet = Umbraco.Core.ApplicationContext.Current.DatabaseContext.Database.Fetch<SchoolDB>("SELECT * FROM _schools WHERE state='" + strState + "' AND County='" + strCounty + "' AND Active=1 ORDER BY SchoolName;");
}
if (oRet != null)
{
//TimeSpan ts = new TimeSpan(14, 0, 0, 0);
//DateTime dtToday = DateTime.Now - ts;
DateTime dtToday = DateTime.Now;
//string strToday = string.Format("{0}-{1}-{2}", dtToday.Year, dtToday.Month, dtToday.Day);
foreach (SchoolDB sch in oRet)
{
sch.listsSchoolClubs = LoadSchoolClubs("WHERE SchoolId = " + sch.id + " AND Active=1") ;
foreach ( SchoolClubDB o in sch.listsSchoolClubs)
{
if ( o.RegistrationClosedDate < dtToday)
{
//o.ClubName = o.ClubName + "(Closed)";
o.id = -1;
}
}
}
}
}
catch ( Exception ex)
{
CCCommon.Support.WriteErrorExceptionEvent(ex, "LoadSchools", strState + "," + strCounty);
}
return oRet;
}
public static List<SchoolDB> LoadSchools()
{
List<SchoolDB> oRet = null;
try
{
oRet = Umbraco.Core.ApplicationContext.Current.DatabaseContext.Database.Fetch<SchoolDB>("SELECT * FROM _schools ORDER BY SchoolName;");
}
catch (Exception ex)
{
CCCommon.Support.WriteErrorExceptionEvent(ex, "LoadSchools", "");
}
return oRet;
}
public static SchoolDB LoadSchool(int iSchoolId)
{
SchoolDB oRet = null;
try
{
oRet = Umbraco.Core.ApplicationContext.Current.DatabaseContext.Database.Single<SchoolDB>("SELECT * FROM _schools WHERE id=" + iSchoolId.ToString());
if (oRet != null)
{
oRet.listsSchoolClubs = LoadSchoolClubs("WHERE SchoolId = " + iSchoolId.ToString() );
}
}
catch (Exception ex)
{
CCCommon.Support.WriteErrorExceptionEvent(ex, "LoadSchool", "Schoolid: " + iSchoolId.ToString());
}
return oRet;
}
public static List<SchoolClubDB> LoadSchoolClubs(string strWhere)
{
List<SchoolClubDB> oRet = null;
int iRetryCount = 0;
while (oRet == null && iRetryCount <= 2)
{
try
{
oRet = Umbraco.Core.ApplicationContext.Current.DatabaseContext.Database.Fetch<SchoolClubDB>("SELECT * FROM _schoolClubs " + strWhere + ";");
}
catch (Exception ex)
{
++iRetryCount;
CCCommon.Support.WriteErrorExceptionEvent(ex, "LoadSchoolClubs",strWhere );
CCCommon.Support.WriteInfoEvent("LoadSchoolClubs", "Retrying: " + iRetryCount.ToString());
System.GC.Collect();
System.Threading.Thread.Sleep(1000);
}
}
return oRet;
}
}
}
I am trying to locate the exact source code for 7.4.3 assembly:
1.0.5948.18141. I can't seem to find that on github, can you let me know
where it can be found? I would like to see if I can determine where this is
occurring even going so far as to rebuild with more logging in to help me get past this problem.
In an attempt to try to rule items out, I created a class library and in that library bypassed petapoco by going direct to mysql using my mysql.data and readers. My previous attempt at this was direct mysql readers inside of my umbraco project which failed miserably and interfered with umbracos connections. Moving the mysql client logic out to a class library allows me to have my own database connection and call mysql directly without interfering with umbraco database connections.
I then created a layer where I would copy the objects from the classes in the class library over directly into my model classes in my umbraco project. It is very inefficient but I am really trying to determine exactly where the problem lies not fix it this way.
What I found out, is that once I do that I can no longer reproduce the issue nor any issue for that matter. This is not a solution I plan to stick with, i was trying to rule out another variable, in this case if the problem followed I would have began to suspect mySQL or my upper level code. But since the problem went away, I am still left with thinking it is umbraco/petapoco on top of mysql somehow.
I know you may not have alot of time to examine this, and if you do not, if you could give me some guidance on how to take the results of a debug build of umbraco and apply it to my project so that I can find the problem myself that would be helpful as well. I already have the source for umbraco, and built it in VS. But when I try to copy over the binaries into my project,it complains about assembly version mismatches and wants to grab everything again from the package library. So, if it is easier to point me in that direction I can try to fix the issue myself or determine the nature of it.
Thank you and I really appreciate you looking into this, I have to get my system stabilized ASAP.
I originally thought it was due to using a static database context but after changing the code to create the database context as a non static member the problem persisted.
My solution was to NOT use the umbraco petapoco implementation and I switched over to direct mysql and it solved my problem.
Intermittent database exceptions during Fetch operations
I am using Umbraco version 7.4.3 assembly: 1.0.5948.18141
I am getting intermittent exceptions during fetch operations. I have scoured the web for answers and am coming up empty. This is what shows up in my umbraco log file when I get these errors. I have validated that with the same query that works over and over again, that occasionally I get this error. I have added retry logic with garbage collection in the exception handlers and sleep statements, but to no avail. Anything anyone could suggest to shed light on this would be extremely helpful. I am desperate. :)
2016-11-03 10:49:12,240 [P2872/D6/T1120] ERROR Umbraco.Core.Persistence.UmbracoDatabase - Database exception occurred System.NullReferenceException: Object reference not set to an instance of an object. at Umbraco.Core.Persistence.Database.
Hey - A nullref exception in Database is a weird thing. In addition, it looks like the stack trace gets truncated in the log (ie contains only 1 line) - or is it you filtering the lines?
Could you post more of the log, including some context (what happens before and after)? And make sure it is properly formatted as your original post is garbled?
Also, can you give a bit of context about the query itself, where it runs (controller, view...)?
Stephen,
I am attaching a text file that contains some more background and details about what is going on. I did not trim the log entries, the entries in the Umbraco log except is the only exception information at the time of the error. I appreciate you looking into this, it has me scratching my head and my next step is probably going to upgrade to 7.5 to see if that helps, but that is a bigger task since I have to test it on my dev and qa environments before rolling it out to prod and that is a pretty big task.
Thank you!
Robert
Text File Contents:
Background:
I tried bypassing Petapoco all together and going directly to mySQL itself to no avail. Connecting and executing readers myself just broke umbraco after that.
mySql is running will full efficiency, or so the dashboard and logs indicate. This error happens about 15% of the time and this is a rough estimate. Sometimes I see it more often then not and sometimes I don't see it for hours of high useage.
modifying the web.config:
This resolved the multiple app pool shutdowns in the log, but did not resolve the issue below.
Details:
This code is called everytime a user logs into the system as well as various times during the user experience.
The code that matches the exception you see below is what I am calling to fetch the results:
NOTE: The Retry code was a desperate attempt to work around the problem to no avail.
This exception is from my own logging that I generate in the exception handler above. It is a little redundant since I dump a full stack trace after the initial one.
--------------------------- My Custom Log -----------------------------
2016-11-14 20:17:57.8443 Error: Browser: Safari IP: 24.98.214.237 HOST: 24.98.214.237 : LoadSchoolClubs: WHERE SchoolId=34 System.NullReferenceException: Object reference not set to an instance of an object. at Umbraco.Core.Persistence.Database.
--------------------------------- End My Custom Log ------------------------------------
--------------------------------- Umbraco Log Entries that occur at same time -----------
System.NullReferenceException: Object reference not set to an instance of an object. at Umbraco.Core.Persistence.Database.
------------------------------- End Umbraco Log ---------------------------------------
So what is causing the error is a simple fetch:
and the error is a null reference exception when iterating over the records that are being read. Considering that it works some of the time, and that "retrying" does not improve the situation... I'd be tempted to think about an issue with data.
What does the
SchoolClubDB
class look like, and is it possible that in some cases, what is returned by the database causes the class to fail to initialize properly?Try to omit the "SELECT * FROM _schoolClubs". It worked for me. The query that gets generated by petapoco is different between:
this:
and this:
You can see it if you use the sql profiler. Second one is better, faster and less error prone.
Stephen,
Since I am not sure what the underlying problem is, I can't say for certain. What I can say, is the the query uses the primary key (id) to do the fetch. It is unique in the tables and there are only about 70 different rows in that table. The class itself is included for your edification.
The data itself for the various rows once configured is pretty static, and I would execute the same code myself when I see the entries in the logs, and the same ones would work. I.E. Where SchoolId=34, will throw the exception in the logs, but then again with the same schooldId and no underlying data change will work when I try it again. I am not sure if this answers your question, I would love to find this to be a coding issue because I could fix it. At the moment though I am unsure what is causing this.
Now, one thing I just changed to see what will happen based on your question, is I added a [ignore] decoration to the listSchoolClubs variable. I am not sure if that is even examined during the fetch or query, but figured it can't hurt since it is a variable intended to hold a subset of children items not related to a specific database entry.
Here is the class for the SchoolDB:
Stephen,
1.0.5948.18141. I can't seem to find that on github, can you let me know where it can be found? I would like to see if I can determine where this is occurring even going so far as to rebuild with more logging in to help me get past this problem.
Thanks!
Robert
Some updated information, i am still stumped but I can actually reproduce the problem now. Here is the scenario:
I am beginning to think it has something to do with caching in the database since all I have to now is change users, and execute the same query.
Please any ideas?
Robert
Weird one. Sorry ran a little bit out of time, will look into it next week.
Thank you Stephen,
In an attempt to try to rule items out, I created a class library and in that library bypassed petapoco by going direct to mysql using my mysql.data and readers. My previous attempt at this was direct mysql readers inside of my umbraco project which failed miserably and interfered with umbracos connections. Moving the mysql client logic out to a class library allows me to have my own database connection and call mysql directly without interfering with umbraco database connections.
I then created a layer where I would copy the objects from the classes in the class library over directly into my model classes in my umbraco project. It is very inefficient but I am really trying to determine exactly where the problem lies not fix it this way.
What I found out, is that once I do that I can no longer reproduce the issue nor any issue for that matter. This is not a solution I plan to stick with, i was trying to rule out another variable, in this case if the problem followed I would have began to suspect mySQL or my upper level code. But since the problem went away, I am still left with thinking it is umbraco/petapoco on top of mysql somehow.
I know you may not have alot of time to examine this, and if you do not, if you could give me some guidance on how to take the results of a debug build of umbraco and apply it to my project so that I can find the problem myself that would be helpful as well. I already have the source for umbraco, and built it in VS. But when I try to copy over the binaries into my project,it complains about assembly version mismatches and wants to grab everything again from the package library. So, if it is easier to point me in that direction I can try to fix the issue myself or determine the nature of it.
Thank you and I really appreciate you looking into this, I have to get my system stabilized ASAP.
Robert
Hi Robert
I know it's been a long time, but did you ever solve this?
I have a 7.4.1 solution doing something similar. Not using mysql though.
I originally thought it was due to using a static database context but after changing the code to create the database context as a non static member the problem persisted.
My solution was to NOT use the umbraco petapoco implementation and I switched over to direct mysql and it solved my problem.
Not sure if this helps or not.
Robert
is working on a reply...