Trace Log filling with Umbraco.Core.Persistence.UmbracoDatabase warning
I have an Umbraco 6.1.6 site that I've moved from develpment on my local envrionment to the remote live server where it will be hosted. It appears to be working perfectly - I can create pages, publish and everything works OK.
But I noticed the UmbracoTraceLog.txt files (in /App_Data/Logs/) are full of the following warning.
2013-12-23 00:00:51,499 [8] INFO Umbraco.Core.Persistence.UmbracoDatabase - [Thread 19] at System.Data.SqlClient.SqlConnection.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.SqlDataReader.TryHasMoreRows(Boolean& moreRows)
at System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)
at System.Data.SqlClient.SqlDataReader.Read()
at Umbraco.Core.Persistence.Database.<Query>d__1c`1.MoveNext()
This same warning seems to get logged exactly every hour on the hour.
It can connect to the remote DB OK, so not sure what this means?
Can't say that I've seen this before, but its logged at INFO and not a Warning or Error, so not sure I would worry too much about it. But does seem strange that its logged every hour. Do you have any scheduled tasks or the built in 'publish at'-functionality running? With the mention of "Query" and move next my guess would be that the list of 'publish at' or 'remove at' entries is empty and thus "failing" at move next when .ToList() is called on the Database.Query<> (which we do to avoid lazy loading on closed connections).
I checked and there are no scheduled jobs or scheduled publishes. I haven't got any custom scheduled events either.
What is really weird is that in todays trace log this entry is logged exactly every hour on the hour (almost to the millsecond). However, if I check yesterday's trace log it happened (for a period) exactly every minute (to the millsecond)! This has only started happening since it was moved to the live server.
Example times from today (every hour):
2013-12-23 00:00:51,499
2013-12-23 00:01:51,484
2013-12-23 00:02:51,484
2013-12-23 00:03:51,484
etc.
Example times from yesterday (every minute):
2013-12-22 21:44:50,984
2013-12-22 21:45:50,984
2013-12-22 21:46:50,984
2013-12-22 21:47:50,984
etc.
Weird, huh? As you say, it's only logged as INFO, but I'm curious to what it might be?
Don't you get the same log entries locally if you run the site for an hour (boring I know), but would leave out any environment differences.
Other then that do you have any packages installed?
Would also be interesting to know if anything is logged prior to this - like what is using/calling Query on the Database object. As far as I remember the usage of Query is fairly limited in our codebase, although all calls to .Fetch is just a call to .Query with .ToList() so its not an IEnumerable.
I've got all the local tracelogs in SVN and have checked them, but there's no sign of this notification in it.
The packages I have installed are all fairly standard: uComponents, DAMP, Imagen, uTwit
The only thing "unusual" about the site is that it is three sites in one - ie. there are 3 root nodes with host names mapped to them. It's MVC, too. One thing that isn't working on the live version is sending emails (as SMTP isn't configured) but no notifications have been set up.
The version of the site on the remote server (with the unusual log entries) does connect to SQL on a remote DB on a non-standard port. I can't really think of any other differences, apart from enviornment.
For anyone else encoutering this error - and for Morten's santity - I've finally gotten to the bottom of this...
The problem was due to the fact that the database user on our test environment was set to the language of 'English' (which means US English) and on the live site the user was set to "British English". I think this was screwing the date formats up (as silly Americans like to put the month first :p). So a date like '23/05/2014' is a valid date in British culture, but in US Culture it is invalid.
The reason it was happening so regularly - on the minute - was that the problem was arising when the scheduled publish was being called. The scheduling process queries content by release date, and as the date format was causing an invalid month, this was in turn causing an SQL error - conversion of NVarchar to DateTime error - and thus the exception in the log every minute. I figured this out when calling the scheduled process directly through code and saw the underlying exception.
Dan....I would just like to say, without this post I would be...Up shit creek, without a paddle!
Many thanks for finding the answer to a problem thats had me flumoxed for the best part of two weeks. The really strange thing is I have plenty of older examples of Umbraco that use "British English" as the default language in the DB login and it's never been a problem for me before. So much so, I asked Shannon to look at my build and treat it as a bug!
My 6.1.6 build is now working properly again on our SQL2012/IIS8 box. But strangely changing this on our SQL2008/IIS7 box didn't make any difference.
The default SQLServer language on the older box is (and has always been) British English along with the logins. So I have absolutely no idea why it's suddenly become a problem now.
Thankfully we're moving all of our sites over to the new box, so I'm hoping I wont see this again. On the new box both the server and login langs are just English (US).
I'll close down my ticket now and let Shannon know!
Hi, I agree with Martin. That's a bug and I cannot accept that solution. I've a site where the scheduling publishing is a must and, now, I need to solve or to create a workaround with building a custom code ( plus my customer that is not happy !!! ).
Glad it helped you, Martin! It had me flumoxed for a while, too. I agree, there is definitely something weird going on - like you I'd expect the culture not to matter - and it definitely shouldn't have to be US English (I mean, Umbraco is a Danish product after all!).
Do we have any solution on this issue? I am keep getting below error after Umbraco Upgrade 7.7.4.
2017-10-31 05:41:03,172 [P2208/D9/T42] ERROR Umbraco.Core.Persistence.UmbracoDatabase - Exception (bafb4ef0).
System.InvalidOperationException: Invalid attempt to call Read when reader is closed.
at System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)
at System.Data.SqlClient.SqlDataReader.Read()
at Umbraco.Core.Persistence.Database.<Query>d__74`1.MoveNext()
2017-10-31 05:41:03,172 [P2208/D9/T42] ERROR Handyman.usercontrols.TaskDetails - Error: While binding related projects for Project ID: 67500
System.InvalidOperationException: Invalid attempt to call Read when reader is closed.
at System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)
at System.Data.SqlClient.SqlDataReader.Read()
at Umbraco.Core.Persistence.Database.<Query>d__74`1.MoveNext()
at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at System.Linq.Enumerable.WhereEnumerableIterator`1.MoveNext()
at System.Linq.Enumerable.<TakeIterator>d__24`1.MoveNext()
at System.Web.UI.WebControls.Repeater.AddDataItemsIntoItemsArray(IEnumerable dataSource, Boolean useDataSource)
at System.Web.UI.WebControls.Repeater.PostGetDataAction(IEnumerable dataSource)
at System.Web.UI.WebControls.Repeater.CreateControlHierarchy(Boolean useDataSource)
at System.Web.UI.WebControls.Repeater.OnDataBinding(EventArgs e)
at System.Web.UI.WebControls.Repeater.DataBind()
at Handyman.usercontrols.TaskDetails.BindRelatedProjects()
Trace Log filling with Umbraco.Core.Persistence.UmbracoDatabase warning
I have an Umbraco 6.1.6 site that I've moved from develpment on my local envrionment to the remote live server where it will be hosted. It appears to be working perfectly - I can create pages, publish and everything works OK.
But I noticed the UmbracoTraceLog.txt files (in /App_Data/Logs/) are full of the following warning.
This same warning seems to get logged exactly every hour on the hour.
It can connect to the remote DB OK, so not sure what this means?
Any idea what it could be?
Can't say that I've seen this before, but its logged at INFO and not a Warning or Error, so not sure I would worry too much about it. But does seem strange that its logged every hour. Do you have any scheduled tasks or the built in 'publish at'-functionality running? With the mention of "Query" and move next my guess would be that the list of 'publish at' or 'remove at' entries is empty and thus "failing" at move next when .ToList() is called on the Database.Query<> (which we do to avoid lazy loading on closed connections).
Just a guess
- Morten
Thanks for your input, Morten.
I checked and there are no scheduled jobs or scheduled publishes. I haven't got any custom scheduled events either.
What is really weird is that in todays trace log this entry is logged exactly every hour on the hour (almost to the millsecond). However, if I check yesterday's trace log it happened (for a period) exactly every minute (to the millsecond)! This has only started happening since it was moved to the live server.
Example times from today (every hour):
2013-12-23 00:00:51,499
2013-12-23 00:01:51,484
2013-12-23 00:02:51,484
2013-12-23 00:03:51,484
etc.
Example times from yesterday (every minute):
2013-12-22 21:44:50,984
2013-12-22 21:45:50,984
2013-12-22 21:46:50,984
2013-12-22 21:47:50,984
etc.
Weird, huh? As you say, it's only logged as INFO, but I'm curious to what it might be?
Don't you get the same log entries locally if you run the site for an hour (boring I know), but would leave out any environment differences.
Other then that do you have any packages installed?
Would also be interesting to know if anything is logged prior to this - like what is using/calling Query on the Database object. As far as I remember the usage of Query is fairly limited in our codebase, although all calls to .Fetch is just a call to .Query with .ToList() so its not an IEnumerable.
- Morten
I've got all the local tracelogs in SVN and have checked them, but there's no sign of this notification in it.
The packages I have installed are all fairly standard: uComponents, DAMP, Imagen, uTwit
The only thing "unusual" about the site is that it is three sites in one - ie. there are 3 root nodes with host names mapped to them. It's MVC, too. One thing that isn't working on the live version is sending emails (as SMTP isn't configured) but no notifications have been set up.
The version of the site on the remote server (with the unusual log entries) does connect to SQL on a remote DB on a non-standard port. I can't really think of any other differences, apart from enviornment.
Dan
For anyone else encoutering this error - and for Morten's santity - I've finally gotten to the bottom of this...
The problem was due to the fact that the database user on our test environment was set to the language of 'English' (which means US English) and on the live site the user was set to "British English". I think this was screwing the date formats up (as silly Americans like to put the month first :p). So a date like '23/05/2014' is a valid date in British culture, but in US Culture it is invalid.
The reason it was happening so regularly - on the minute - was that the problem was arising when the scheduled publish was being called. The scheduling process queries content by release date, and as the date format was causing an invalid month, this was in turn causing an SQL error - conversion of NVarchar to DateTime error - and thus the exception in the log every minute. I figured this out when calling the scheduled process directly through code and saw the underlying exception.
So something to think about!
So, How solve? I've the same problem with italian culture. I configure the db and db user with English language, but don't solve anything.
Where are saved scheduled data into Umbraco db?
Dan....I would just like to say, without this post I would be...Up shit creek, without a paddle!
Many thanks for finding the answer to a problem thats had me flumoxed for the best part of two weeks. The really strange thing is I have plenty of older examples of Umbraco that use "British English" as the default language in the DB login and it's never been a problem for me before. So much so, I asked Shannon to look at my build and treat it as a bug!
My 6.1.6 build is now working properly again on our SQL2012/IIS8 box. But strangely changing this on our SQL2008/IIS7 box didn't make any difference.
The default SQLServer language on the older box is (and has always been) British English along with the logins. So I have absolutely no idea why it's suddenly become a problem now.
Thankfully we're moving all of our sites over to the new box, so I'm hoping I wont see this again. On the new box both the server and login langs are just English (US).
I'll close down my ticket now and let Shannon know!
Kind Regards
Martin
Thinking about this....I still believe it to be a bug!
Because, we're not all American English! ;)
I'll update the ticket.
M.
Hi, I agree with Martin. That's a bug and I cannot accept that solution. I've a site where the scheduling publishing is a must and, now, I need to solve or to create a workaround with building a custom code ( plus my customer that is not happy !!! ).
Glad it helped you, Martin! It had me flumoxed for a while, too. I agree, there is definitely something weird going on - like you I'd expect the culture not to matter - and it definitely shouldn't have to be US English (I mean, Umbraco is a Danish product after all!).
Do we have any solution on this issue? I am keep getting below error after Umbraco Upgrade 7.7.4.
Bipin did you find a fix for your error? I have one which is similar.
is working on a reply...