U4-5728 - OriginalRequestUrl not initialized, KeepAlive or ScheduledPublishing run too soon

Note: ApplicationContext.IsReady is set by the boot manager, so before the module has set OriginalRequestUrl, so it cannot be used here - will have to either create something else, or refactor .IsReady, or test for null string.

Related: http://our.umbraco.org/forum/core/general/56407-Worrying-errors-in-the-logs-over-last-couple-of-days-from-UmbracoWebSchedulingScheduledPublishing-

Pushed 0f4436a465eabbdd76ad960422860b827a479c93 to 7.2.0 - test whether the original request is null/empty and issue a warning and do not try to run services. Should get rid of the "worrying errors". @sebastiaan ?

It's a good start, but to be honest, we really need to figure out somehow why the URL is empty. Now scheduled publishing will just not work and fail. I'd much rather try to build the URL again if it's empty (as a temporary workaround) until we can actually figure out where the actual problem comes from (logically, it should almost not be possible that the URL is empty).

Also.. it's funny that ScheduledPublishing passes auth headers in and KeepAlive does not, should probably centralize that logic.

The only reason I can see for the URL to be empty is if it's not been initialized yet, meaning that the boot manager has configured the scheduled tasks to run, but for some reason the first request has not begun yet (maybe because it's causing all sorts of things that take time, to happen) and has not set the URL. So, we'll not run the scheduled tasks - while the url is empty. But it cannot remain empty for very long. The first request, when it runs, will set it to something. So we're only skipping tasks while Umbraco gets ready but then they'll run. I'm (almost) certain of that so in my mind it's not a workaround - just taking care of the inevitable period of time between scheduled tasks configuration & first request completion. Making sense?

Makes sense. I'll ask some follow-up questions in the related Our thread to confirm this (wondering if updating the fcnMode will help in their case as well, if so then that's likely the cause of this issue, if not then it's worth looking into deeper).

We can also change the scheduler to start at the end of a first request instead of starting it where it is now, that way we can guarantee that the first request executed and was successful

I've changed the scheduler now:

• Tasks are now web aware using the background task runner i made on new courier
• The schedules don't actually start until after the first successful request is complete when the application and db are configured.

If you're on 6.2.4, I've added patched dlls that contain the changes above for 6.2.4 as well, unzip in your bin folder.

I've installed the 6.2.4 patch, and the errors are gone. Thanks, Sebastiaan!

@sebastiaan: After installing the patch for 6.2.4 the initial errors were gone, but this morning at around 5:10am we started seeing a different error every minute. We're running a non-load balanced site on HTTPS on a Win2008R2/IIS7 server, umbracoUseSSL is set to true in the web.config.

2014-11-25 05:10:02,678 [7] ERROR Umbraco.Web.Scheduling.ScheduledPublishing - [Thread 11] An error occurred with the scheduled publishing System.Net.WebException: The underlying connection was closed: An unexpected error occurred on a send. ---> System.IO.IOException: The handshake failed due to an unexpected packet format. at System.Net.Security.SslState.StartReadFrame(Byte[] buffer, Int32 readBytes, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslState.StartReceiveBlob(Byte[] buffer, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslState.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslState.ForceAuthentication(Boolean receiveFirst, Byte[] buffer, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslState.ProcessAuthentication(LazyAsyncResult lazyResult) at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Net.TlsStream.ProcessAuthentication(LazyAsyncResult result) at System.Net.TlsStream.Write(Byte[] buffer, Int32 offset, Int32 size) at System.Net.ConnectStream.WriteHeaders(Boolean async) --- End of inner exception stack trace --- at System.Net.WebClient.UploadDataInternal(Uri address, String method, Byte[] data, WebRequest& request) at System.Net.WebClient.UploadString(Uri address, String method, String data) at Umbraco.Web.Scheduling.ScheduledPublishing.Run() 2014-11-25 05:10:02,678 [7] ERROR Umbraco.Web.Scheduling.KeepAlive - [Thread 9] Error in ping System.Net.WebException: The underlying connection was closed: An unexpected error occurred on a send. ---> System.IO.IOException: The handshake failed due to an unexpected packet format. at System.Net.Security.SslState.StartReadFrame(Byte[] buffer, Int32 readBytes, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslState.StartReceiveBlob(Byte[] buffer, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslState.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslState.ForceAuthentication(Boolean receiveFirst, Byte[] buffer, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslState.ProcessAuthentication(LazyAsyncResult lazyResult) at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Net.TlsStream.ProcessAuthentication(LazyAsyncResult result) at System.Net.TlsStream.Write(Byte[] buffer, Int32 offset, Int32 size) at System.Net.ConnectStream.WriteHeaders(Boolean async) --- End of inner exception stack trace --- at System.Net.WebClient.DownloadDataInternal(Uri address, WebRequest& request) at System.Net.WebClient.DownloadString(Uri address) at Umbraco.Web.Scheduling.KeepAlive.Start(ApplicationContext appContext)

Why on earth has this not been added to 6.2.5?

Some additional info regarding the errors in version 6.2.4 (with patch U4-5728 installed). These errors start occuring after an application pool recycle. So strangely enough, when I touch the web.config the errors are gone, but after a scheduled recycle (at 5:00am) the errors pop up again?

@creativesuspects Can you find the log entry where it says:

INFO Umbraco.Web.UmbracoModule - [Thread 12] Setting OriginalRequestUrl:

Have a look at the URL, what does it say? It could be there multiple times and it could differ after you touch the web.config. I've been running this since you created the issue and not seen your problem in my logs. I'm on win2012R2 though and it could well be a configuration issue with certificates (which I'm no expert in, so don't look at me.. all I know is what I can learn about this error from Google.. :))

One more thing, I have url rewriting for IIS installed and added this rule, might help (although I still fail to see why your context is different after touching web.config as opposed to an app pool recycle):

@sebastiaan Here you go:

Setting OriginalRequestUrl: localhost:80/umbraco

I was using the following rewrite in UrlRewriting.config to force HTTPS:

I've deactivated this rewrite. And configured the rule you suggested in the web.config. It looks like changing the way the server forces HTTPS also affected the OriginalRequestUrl, which now shows:

Setting OriginalRequestUrl: domain.com:443/umbraco

@creativesuspects Aha, interesting. So this workaround works for you now? Or should we wait until 5AM tomorrow to make sure? Ps. localhost instead of domain.com is pretty interesting (read: weird).

@sebastiaan I just did a manual app pool recycle. So far so good. I'll keep an eye on those logs, and I'll post an update here tomorrow. Could the rewrite I had configured in the UrlRewriting.config have caused the ''weird'' OriginalRequestUrl?

The OriginalRequestUrl seems okay at the moment, even after the manual app pool recycle:

[159] INFO Umbraco.Core.UmbracoApplicationBase - [Thread 167] Application shutdown. Reason: HostingEnvironment [7] INFO Umbraco.Web.UmbracoModule - [Thread 13] Setting OriginalRequestUrl: domain.com:443/umbraco

My guess would be that you don't have a hostname configured in IIS, this is the only site running? In which case once Umbraco wakes up and it pings the scheduledpublishing, it doesn't know the url, so it just takes localhost. Could that be it?

Either that or you don't have a hostname configured in Umbraco itself, that could actually be more likely.

@sebastiaan You're right, I haven't configured a hostname in Umbraco, since there's only one hostname bound to this particular IIS website. I'm using the following multilingual setup:

Content |--LanguageRedirect (Domain: not set, Language: Inherit, redirects user to language site based on cookie) |--EN (Domain: not set, Language: en-GB) |--NL (Domain: not set, Language: nl-NL)

Does this have any negative effect on Umbraco funtionality? Would it be better to configure the hostnames in Umbraco as follows:

Content |--LanguageRedirect (Domain: domain.com, Language: en-GB) |--EN (Domain: domain.com/en, Language: en-GB) |--NL (Domain: domain.com/nl, Language: nl-NL)

Do I have to include https:// in the domain settings, since it's running on SSL?

The code that sets that URL is here:

https://github.com/umbraco/Umbraco-CMS/blob/7.2.0/src/Umbraco.Web/UmbracoModule.cs#L53

It has nothing to do with setting up hostnames in Umbraco, it just detects the current one

It's VERY important to note this fix too:

http://issues.umbraco.org/issue/U4-5564

which will directly affect you because the code previous to 7.2 didn't set this correctly with SSL.

@Shandem Looks like this hasn't been fixed in version 6.2.5. Do you have any idea if it's been reported as a bug for version 6.x.x?

@sebastiaan Replacing the "force HTTPS" rewrite in UrlRewriting.config with the rewrite rule you suggested seems to have fixed the issue for me. No more errors in the logs after app pool recycles. Still leaves the question if not configuring hostnames in Umbraco could have a negative effect on Umbraco functionality? And if the bug mentioned by Shannon will be fixed in the next version 6.2.x as well?

@sebastiaan Also, has the 6.2.4 patch you provided been included in version 6.2.5?

@Shandem That SSL switching is included in de patch. @creativesuspects I changed my mind, it's got nothing to do with the URL configured in Umbraco (I don't have one either).I can replicate the error when I don't have the IIS redirect configured. I think it's just that the first request seems to come in over port 80 and that doesn't match with the subsequent SSL requests. Not sure what the problem is or how to fix it apart from the IIS redirect above.

I'll create a separate issue specifically for this so i can look at it

I've created a pull request with a fix for issue U4-5564 in the 6.2.x line: https://github.com/umbraco/Umbraco-CMS/pull/569

We are still experiencing this issue on multiple Umbraco 6.2.4 websites. We tried using the Umbraco.6.2.4-patch-U4-5728 but that didn't fix the problem.

@Michel Are you using any rewrites/redirects in the UrlRewriting.config?

@sebastiaan Any idea if you'll be able to include this pull request in the next 6.2.x release? https://github.com/umbraco/Umbraco-CMS/pull/569

Same issue here in 6.2.4. After installing the patch for 6.2.4 exactly the same errors like Arjan Hoogervorst has posted at 25 Nov 2014, 09:39. Hosting Environment: Windows Server 2008 R2, IIS 7.5 Configurations: no rules in UrlRewriting.config, umbracoUseSSL is set to false

@oohnajra Hi, thanks for your quick reaction! Yes we do got some rules written in the UrlRewriting.config, but only the default ones.

@Michel Are you using a "Force HTTPS" rule in the UrlRewriting.config? Because that was causing issues in my configuration.

@oohnajra great that you fixed it on your website! But no we are not using "Force HTTPS", we even tried without the UrlRewriting.config rules.

The error we are receiving looks a little different from the error you got earlier. I'm thinking about making a new post on this.

2014-12-04 16:36:23,465 [8] ERROR Umbraco.Web.Scheduling.KeepAlive - [Thread 28] Error in ping System.Net.WebException: The operation has timed out at System.Net.WebClient.DownloadDataInternal(Uri address, WebRequest& request) at System.Net.WebClient.DownloadString(Uri address) at System.Net.WebClient.DownloadString(String address) at Umbraco.Web.Scheduling.KeepAlive.Start(ApplicationContext appContext) 2014-12-04 16:36:23,762 [8] ERROR Umbraco.Web.Scheduling.ScheduledPublishing - [Thread 14] An error occurred with the scheduled publishing System.Net.WebException: The operation has timed out at System.Net.WebClient.UploadDataInternal(Uri address, String method, Byte[] data, WebRequest& request) at System.Net.WebClient.UploadString(Uri address, String method, String data) at System.Net.WebClient.UploadString(String address, String data) at Umbraco.Web.Scheduling.ScheduledPublishing.Run()

@all if you're having issues, it would REALLY help to know the OriginalRequestUrl which is also logged in your log files.

@Michel Have you tried creating a custom 6.2.4 build with the following fix: https://github.com/umbraco/Umbraco-CMS/pull/569/files

@oohnajra That's not enough to fix this. I have the code from this comment http://issues.umbraco.org/issue/U4-5728#comment=67-17467 on my crashed computer and I can push it next week.

Commit made by '''Sebastiaan Janssen''' on ''2014-12-07T16:16:29+01:00'' https://github.com/umbraco/Umbraco-CMS/commit/4eb9a54fa5d4e0330b6adc178191221d41fde165

Ports v7 changes for U4-5728 - OriginalRequestUrl not initialized, KeepAlive or ScheduledPublishing run too soon

#U4-5728

@Michel Can you look in your logs and find out what it says for "Setting OriginalRequestUrl:" right before you see this error? Also, on the server where this is running can you then go to the URL that is mentioned in "Setting OriginalRequestUrl:" to make sure you're not blocking something with firewall rules or something like that?

@SörenDeger Same question for you, can you look at "Setting OriginalRequestUrl:" and see if the URL is accessible?

Oh and one more thing @Michel and @SörenDeger - have you installed Umbraco using NuGet?? If you are using NuGet then please note that every time you build your solution, the ORIGINAL 6.2.4 dlls get copied back into your bin folder, overwriting the patched dlls. So make sure that you have an afterbuild action that copies the patched dlls in. Once these problems are fixed we'll release 6.2.5 including a NuGet package so that you don't have that problem any more. So please please check that you definitely have the patched dlls in your bin folder if you see those errors.

@Sebastiaan Thank you. The Url is not accessible from server. Our administrator will review it. The site is on a very shielded customer server. Maybe this can solved it. I'll give you an answer as soon as I have a feedback.

And no, we haven't using NuGet and yes, the patched dlls are in bin folder.

@sebastiaan The url is accessible from server and it works now :) This solved the issue for us.

Hi all, I still have issues with KeepAlive/ScheduledPublishing. read about this yesterday and updated the installation it was affecting from 7.1.8 to 7.1.9. And it seemed to work for 1-2 hours, no timeouts and hanging of the website. Approx 2 hours later, the site hangs and times out.

2014-12-17 11:08:44,063 [19] ERROR Umbraco.Web.Scheduling.ScheduledPublishing - [Thread 40] An error occurred with the scheduled publishing System.Net.WebException: Unable to connect to the remote server ---> System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond 195.190.31.159:80 at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress) at System.Net.ServicePoint.ConnectSocketInternal(Boolean connectFailure, Socket s4, Socket s6, Socket& socket, IPAddress& address, ConnectSocketState state, IAsyncResult asyncResult, Exception& exception) --- End of inner exception stack trace --- at System.Net.WebClient.UploadDataInternal(Uri address, String method, Byte[] data, WebRequest& request) at System.Net.WebClient.UploadString(Uri address, String method, String data) at Umbraco.Web.Scheduling.ScheduledPublishing.Run() 2014-12-17 11:09:03,861 [19] ERROR Umbraco.Web.Scheduling.KeepAlive - [Thread 14] Error in ping System.Net.WebException: Unable to connect to the remote server ---> System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond 195.190.31.159:80 at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress) at System.Net.ServicePoint.ConnectSocketInternal(Boolean connectFailure, Socket s4, Socket s6, Socket& socket, IPAddress& address, ConnectSocketState state, IAsyncResult asyncResult, Exception& exception) --- End of inner exception stack trace --- at System.Net.WebClient.DownloadDataInternal(Uri address, WebRequest& request) at System.Net.WebClient.DownloadString(Uri address) at Umbraco.Web.Scheduling.KeepAlive.Start(ApplicationContext appContext, IUmbracoSettingsSection settings)

Any feedback would be much appreciated.

And just so I don't forget, I've copied the whole installation to our servers as well, here the site never hangs or have any performance issues. Identical sites (both 7.1.8 and 7.1.9) but just runs as it should, the problem only occurs at the clients hosting-provider it seems.

@Samanci Same question for you, can you look at "Setting OriginalRequestUrl:" and see if the URL is accessible?

@sebastiaan looked at the "Setting OriginalRequestUrl:" sent it to the support team at the hosting provider, and seems accessible from the server (send me a screendump of the Umbraco-login screen as the url was www.domainname.dk:80/umbraco

@Samanci Are you sure that there's a "/" before the ":80" because that would be the actual problem. That's not going to work..

@sebastiaan Sorry, my slippery fingers

@Samanci Ah, but I completely didn't ready your error message before: A connection attempt failed because the connected party did not properly respond after a period of time. This has nothing to do with the issue at hand but the log error just shows you that something is not working properly on your host's server, as you have seen as well because the whole site becomes unresponsive, if the same site works fine on your own server then it's something for the hosting provider to figure out. :)

@sebastiaan thx alot, will take it up with the hosting provider.

EDIT: My problem seems to be IP-related at the hosting provider, thx for helping me pin-point the issue and sorry for taking up space but this was a good excuse to finally be a part of the community :)

@Samanci A good excuse indeed! No worries, glad to have it verified that we did our fixing correctly. :-)

@sebastiaan I had this issue last week, and I thought I had fixed it by adding a baseURL to my scheduledTasks setting (scheduledTasks baseUrl="client1.mydomain.com.au/umbraco/").

But I've had another occurrence of the issue where all my websites stopped responding... looking in the logs I can see this line "Setting OriginalRequestUrl: localhost:80/umbraco". It appears that Umbraco restarted itself just beforehand, and incorrectly setting the URL to "localhost" makes everything fall over completely (ALL Umbraco websites stop being served).

My umbraco install (version 7.2.6) is running several websites, and IIS doesn't have any hostname assigned to it as I want it to accept any domain name that points to it, and it serves out on a single IP address. The server has 4 different IP addresses (other IP addresses are for non-umbraco sites), and "localhost" isn't pointing to anything at all (on port 80).

But what's weird is that after my client reported the issue, I manually restarted the IIS site (not the whole service) and the log then shows "Setting OriginalRequestUrl: client2.mydomain.com.au:80/umbraco" which IS correct. I don't know why it was detected as "localhost" previously.

Even later still I see another restart (probably due to me fiddling with IIS) and it shows two lines right after each other:

Setting OriginalRequestUrl: client1.mydomain.com.au:80/umbraco Setting OriginalRequestUrl: client2.mydomain.com.au:80/umbraco

Note: I have the "client1" URL set in scheduled tasks setting, while "client2" is the first website in the umbraco admin.

Any ideas how I can force the baseURL to always be set to either the domain I specified in scheduledTasks (or elsewhere), OR to just use the IP address assigned in IIS? I really don't want to rely on auto-detection when it is causing so many issues for me.

BTW I don't have any rewrites in UrlRewriting.config, I am currently not using https/ssl, and it's not a load-balanced server either

Hi, firstly, the logging doesn't indicate what the BaseUrl is, you can see that here:

https://github.com/umbraco/Umbraco-CMS/blob/dev-v7/src/Umbraco.Web/UmbracoModule.cs#L51

The log outputs what it auto-detects as the first request URL, this doesn't mean that is what it is using for the BaseUrl for scheduled tasks. The URL used for scheduled tasks is resolved from here:

https://github.com/umbraco/Umbraco-CMS/blob/dev-v7/src/Umbraco.Core/Sync/ServerEnvironmentHelper.cs#L117

(and here: https://github.com/umbraco/Umbraco-CMS/blob/dev-v7/src/Umbraco.Core/Sync/ServerEnvironmentHelper.cs#L23 )

So if the settings.ScheduledTasks.BaseUrl is not null/empty, then it will be used .

Here's the code for scheduled publishing:

https://github.com/umbraco/Umbraco-CMS/blob/dev-v7/src/Umbraco.Web/Scheduling/ScheduledPublishing.cs#L45

If there are errors with that, it will log them, do you have any of those errors? Otherwise perhaps your issues isn't regarding scheduled publishing at all and it is something else entirely? I'm not sure how scheduled publishing can bring down your whole site...

@Shandem looking at the source code you linked, you're correct that it should be using my defined Base URL... and I can see the distinction between the BaseURL and the OriginalRequestUrl. Perhaps OriginalRequestUrl is being set to "localhost" as I have "Preload Enabled" and "Start Automatically" both set to true in IIS? i.e. because the first request after a webserver process recycle would be from the server itself?

Before I set the scheduledtask BaseURL my production website was shutting down daily. It's been running for 3 days since I made the fix on Monday, only to have this issue today. I don't know if it's the scheduledtask or the originalrequesturl or something else that's causing the issue... from what I can tell it's trying to access localhost:80/umbraco and then bombs out all sites when that URL doesn't work.

Here's an extract of my logs, I can't see ANY mention of a shutdown in the logs before 13:55, so I'm not sure why it had to run through the "umbraco application starting" process at 13:55

2015-07-02 13:55:43,659 [10] INFO Umbraco.Core.CoreBootManager - [T1/D2] Umbraco application starting [-- skipped normal startup lines --] 2015-07-02 13:55:56,815 [10] INFO Umbraco.Core.CoreBootManager - [T1/D2] Umbraco application startup complete (took 13050ms) 2015-07-02 13:56:01,379 [10] INFO Umbraco.Web.UmbracoModule - [T5/D2] Setting OriginalRequestUrl: localhost:80/umbraco 2015-07-02 13:56:04,289 [10] INFO umbraco.content - [T5/D2] Load Xml from file... 2015-07-02 13:57:54,729 [10] ERROR umbraco.content - [T5/D2] Failed to load Xml from file. System.Threading.ThreadAbortException: Thread was being aborted. at System.Threading.WaitHandle.WaitOneNative(SafeHandle waitableSafeHandle, UInt32 millisecondsTimeout, Boolean hasThreadAffinity, Boolean exitContext) at System.Threading.WaitHandle.InternalWaitOne(SafeHandle waitableSafeHandle, Int64 millisecondsTimeout, Boolean hasThreadAffinity, Boolean exitContext) at Umbraco.Core.AsyncLock.Lock(Int32 millisecondsTimeout) at umbraco.content.EnsureFileLock() at umbraco.content.LoadXmlFromFile() 2015-07-02 13:57:56,260 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T57/D2] [XmlCacheFilePersister] Terminating 2015-07-02 13:57:56,260 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T57/D2] [XmlCacheFilePersister] Waiting for tasks to complete 2015-07-02 13:57:56,260 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T57/D2] [ScheduledTasks] Terminating 2015-07-02 13:57:56,260 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T57/D2] [ScheduledTasks] Waiting for tasks to complete 2015-07-02 13:57:56,276 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T57/D2] [ScheduledTasks] Tasks completed, terminated 2015-07-02 13:57:56,276 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T69/D2] [XmlCacheFilePersister] Tasks completed, terminated 2015-07-02 13:57:56,339 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T57/D2] [LogScrubber] Terminating 2015-07-02 13:57:56,339 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T57/D2] [LogScrubber] Waiting for tasks to complete 2015-07-02 13:57:56,339 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T57/D2] [LogScrubber] Tasks completed, terminated 2015-07-02 13:57:56,339 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T57/D2] [ScheduledPublishing] Terminating 2015-07-02 13:57:56,339 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T57/D2] [ScheduledPublishing] Waiting for tasks to complete 2015-07-02 13:57:56,339 [10] INFO Umbraco.Web.Scheduling.BackgroundTaskRunner - [T57/D2] [ScheduledPublishing] Tasks completed, terminated 2015-07-02 13:57:56,432 [10] INFO Umbraco.Core.UmbracoApplicationBase - [T23/D2] Application shutdown. Reason: HostingEnvironment

At this point the Umbraco sites don't respond properly - the sites only show a blank page in a browser (not a 404 or error code). I can still login to /umbraco but it fails to load content for any CMS pages when I view them. I have to restart the site in IIS for it to work again...

Are you affected by this? http://issues.umbraco.org/issue/U4-6338 (i.e. are you running Win server 2012 R2 + IIS ) ?

@Shandem no... I am running Server 2012, but it's not R2. I've posted comments in that thread previously (as I thought it was the same issue), but it seems this is a different issue and I can't apply the hotfix to my server version.

Ok, good to know to make sure it's not that issue. The log you posted above, what period was this during? When the site goes down, or ?

That was everything just before the site stopped working... the previous entry (before 13:55) is at 12:57 with a "Log scrubbed" message, and the next log entry (after 13:57) is at 14:16 when I restarted the website in IIS (after the client reported the issue). So it was basically down between 13:57 and 14:16, with no further error messages logged.

I am not entirely sure how the ThreadAbortException is related to scheduled tasks. It appears that for whatever reason, Umbraco is restarting, but cannot get a lock over the xml cache (waits for about 1min 50secs) and then IIS decides to force-stop everything. Which means that ''something'' has the lock and is not releasing it. I'd really love to see the entire log from, say, 10:00 (do not remove anything, just dump the log). Thanks!

Okay, here's the log from 04:57 (a Log Scrubbed entry) until 13:55 (the Application starting entry, which is the first line of the log I posted previously). I can't see anything interesting in there myself... but here you go! (Note: I only edited the domain, IP address and an identifying page name)

2015-07-02 04:57:13,473 [10] INFO umbraco.BusinessLogic.Log - [T42/D2] Log scrubbed. Removed all items older than 2015-05-03 04:57:13 2015-07-02 08:33:35,853 [10] INFO Umbraco.Core.Security.UmbracoMembershipProviderBase - [T69/D2] Login attempt succeeded for username client@somedomain.com.au from IP address 123.456.786.012 2015-07-02 08:33:35,868 [10] INFO Umbraco.Web.Security.WebSecurity - [T69/D2] User Id: 4 logged in 2015-07-02 08:33:36,656 [10] INFO Umbraco.Core.PluginManager - [T37/D2] Starting resolution types of Umbraco.Web.Trees.TreeController 2015-07-02 08:33:36,656 [10] INFO Umbraco.Core.PluginManager - [T37/D2] Completed resolution of types of Umbraco.Web.Trees.TreeController, found 5 (took 0ms) 2015-07-02 08:33:37,125 [10] WARN Umbraco.Core.Services.ApplicationTreeService - [T42/D2] The tree definition: could not be resolved to a .Net object type 2015-07-02 08:33:42,518 [10] WARN Umbraco.Web.Models.Mapping.PreValueDisplayResolver - [T70/D2] Could not find persisted pre-value for field startNodeId 2015-07-02 08:33:47,258 [10] WARN Umbraco.Web.Models.Mapping.PreValueDisplayResolver - [T73/D2] Could not find persisted pre-value for field startNodeId 2015-07-02 08:34:14,475 [10] INFO Umbraco.Core.Publishing.PublishingStrategy - [T66/D2] Content 'Client Homepage' with Id '1069' has been published. 2015-07-02 08:34:18,850 [10] INFO umbraco.content - [T66/D2] Save Xml to file... 2015-07-02 08:34:18,881 [10] INFO umbraco.content - [T65/D2] Saved Xml to file. 2015-07-02 08:35:20,556 [10] INFO Umbraco.Core.Publishing.PublishingStrategy - [T73/D2] Content 'Client Homepage' with Id '1069' has been published. 2015-07-02 08:35:25,009 [10] INFO umbraco.content - [T75/D2] Save Xml to file... 2015-07-02 08:35:25,087 [10] INFO umbraco.content - [T78/D2] Saved Xml to file. 2015-07-02 08:39:22,379 [10] INFO Umbraco.Core.Publishing.PublishingStrategy - [T69/D2] Content 'Privacy Policy' with Id '1109' has been published. 2015-07-02 08:39:26,504 [10] INFO umbraco.content - [T66/D2] Save Xml to file... 2015-07-02 08:39:26,551 [10] INFO umbraco.content - [T68/D2] Saved Xml to file. 2015-07-02 08:57:13,487 [10] INFO umbraco.BusinessLogic.Log - [T91/D2] Log scrubbed. Removed all items older than 2015-05-03 08:57:13 2015-07-02 11:28:40,815 [10] INFO Umbraco.Core.PluginManager - [T17/D2] Starting resolution types of Umbraco.Web.Trees.TreeController 2015-07-02 11:28:40,815 [10] INFO Umbraco.Core.PluginManager - [T17/D2] Completed resolution of types of Umbraco.Web.Trees.TreeController, found 5 (took 0ms) 2015-07-02 11:28:41,096 [10] WARN Umbraco.Core.Services.ApplicationTreeService - [T51/D2] The tree definition: could not be resolved to a .Net object type 2015-07-02 11:31:15,852 [10] INFO Umbraco.Core.Publishing.PublishingStrategy - [T46/D2] Content 'Privacy Policy' with Id '1109' has been published. 2015-07-02 11:31:20,054 [10] INFO umbraco.content - [T42/D2] Save Xml to file... 2015-07-02 11:31:20,085 [10] INFO umbraco.content - [T36/D2] Saved Xml to file. 2015-07-02 11:31:35,822 [10] INFO Umbraco.Core.Publishing.PublishingStrategy - [T60/D2] Content 'Terms and Conditions' with Id '1109' has been published. 2015-07-02 11:31:39,939 [10] INFO umbraco.content - [T60/D2] Save Xml to file... 2015-07-02 11:31:39,955 [10] INFO umbraco.content - [T73/D2] Saved Xml to file.
2015-07-02 12:57:13,489 [10] INFO umbraco.BusinessLogic.Log - [T69/D2] Log scrubbed. Removed all items older than 2015-05-03 12:57:13 2015-07-02 13:55:43,659 [10] INFO Umbraco.Core.CoreBootManager - [T1/D2] Umbraco application starting

@zpqrtbnk does the log help at all? Some sort of lock on the XML does seem likely. If I go into the admin when the site is down, and edit a content page I get this error: "Node XXXX cannot be loaded" (where XXXX is the node id). It looks like it might be similar to this issue, but I'm not sure: http://issues.umbraco.org/issue/U4-6669.

Edit: This issue looks like it's the same as what's happening with me: http://issues.umbraco.org/issue/U4-6626. Specifically this comment: http://issues.umbraco.org/issue/U4-6626#comment=67-20911

At that point I don't know what to think of the log. At 11:31 there's one app domain saving to xml, so it has acquired a lock on the xml. And then at 13:55, out of nowhere, that same app domain (the "D2" thing in the log) decides to start Umbraco, and enters a complete, proper startup... only, it cannot acquire the lock because it's never been released.

What has happened in between? It's as if everything "vanished" without the site really shutting down. Must confess I don't fully understand it all, right now. All I can do is speculate, there are a few things I need to check re. how IIS restarts an entire w3wp.exe. Stay tuned.

Out of curiosity, what was trafic on the site like, between 11:31 and 15:00?

I'd also like to confirm that there is no load balancing going on with this setup right?

@Shandem re-reading this issue, and looking at the code... the point of ApplicationContext.OriginalRequestUrl is really to let the server know how it should talk to itself (ie it should be named eg ''ThisServerUrl''). And by default, we "guess" the value from the first request.

The scheduledTasks/@baseUrl config overrides that setting, so keepAlive &co know how to reach the server. But we still set OriginalRequestUrl from the ''first incoming request'' and that would be why in some cases, we can see the message "Setting OriginalRequestUrl: localhost:80/umbraco" even though BaseUrl is set.

Methink that if BaseUrl is set, we should use it to initialize OriginalRequestUrl, entirely bypassing the "guess from first request" thing.

edit: so in my mind it should be ApplicationContext.ThisServerUrl that by default is guessed from the first request, but can be forced with a ThisServerUrl config of some sort, that's not only for scheduled tasks.

Sure we can do that... unfortunately it doesn't solve this locking issue though ;)

@Shandem sure, just trying to sort out the issues ;-) I'd say there is a "base url" issue - or maybe it's not an issue but it's just confusing. => let's make this http://issues.umbraco.org/issue/U4-6788.

And then there's the restart. Doing some experiments here, and I may be entirely wrong, but what I think we're seeing is an app pool recycle (ie w3wp) where "w3wp-2/domain-2" is starting but "w3wp-1/domain-2" is not going down in time. Would explain why everything in the log is about "domain-2" which seems to be both starting and stopping at the same time. Would love to also have the PID logged.

@Shandem correct - no load balancing, stock standard Windows Server 2012 (not R2), SQL Server 2012 database, standard IIS site. Umbraco site in IIS doesn't have any host header as it's a catch-all on a single IP address. Other non-umbraco sites run on separate IP's

@zpqrtbnk unfortunately I don't have traffic stats at the moment... but it's a new set of sites - one is a demo site, the second is a client site that officially went live this week. Traffic would be super low

@zpqrtbnk I think you're correct that it's tied into the app pool recycle. We were having this issue every 1-2 days before I had configured the "BaseUrl"... it lasted around 3 days after that. So far it's been up again for 3 days again. 1-2 days aligns with a 29 hour pool recyle, but 3ish days doesn't.

Just an update... I experienced the same site shutdown issue on 05/07 and it's just happened again today on 12/07. So it's lasting a lot longer, but I would like for it not to happen at all!

The symptoms always seem the same... it's like the site is trying to recycle, but is failing or timing out and becomes completely unresponsive until manually restarted. There must be some process or request that is stopping it from recycling properly... Any ideas how I can verify what is?

2015-07-12 10:29:21,611 [10] INFO umbraco.content - [T6/D2] Load Xml from file... 2015-07-12 10:31:12,911 [10] ERROR umbraco.content - [T6/D2] Failed to load Xml from file. System.Threading.ThreadAbortException: Thread was being aborted. at System.Threading.WaitHandle.WaitOneNative(SafeHandle waitableSafeHandle, UInt32 millisecondsTimeout, Boolean hasThreadAffinity, Boolean exitContext) at System.Threading.WaitHandle.InternalWaitOne(SafeHandle waitableSafeHandle, Int64 millisecondsTimeout, Boolean hasThreadAffinity, Boolean exitContext) at Umbraco.Core.AsyncLock.Lock(Int32 millisecondsTimeout) at umbraco.content.EnsureFileLock() at umbraco.content.LoadXmlFromFile()

This is echoed in a WebForms section of the site (technically outside Umbraco), that has it's own exception logging and repeats the same "Thread was being aborted" exception. Note that it's a minute after the first exception in the Umbraco log:

#2015.7.12 @ 10:32:40 #VM-SCOOP-01 An error occurred in the function verifyLicence. Page: /WebformSection/default.aspx ##

System.Threading.ThreadAbortException: Thread was being aborted. at umbraco.content.LoadXmlFromFile() at umbraco.content.LoadXmlLocked(SafeXmlReaderWriter safeXml, Boolean& registerXmlChange) at umbraco.content..ctor() at umbraco.content.<.cctor>b__17() at System.Lazy1.CreateValue() --- End of stack trace from previous location where exception was thrown --- at System.Lazy1.get_Value() at Umbraco.Web.PublishedCache.XmlPublishedCache.PublishedContentCache.<get_GetXmlDelegate>b__3(UmbracoContext context, Boolean preview) at Umbraco.Web.PublishedCache.XmlPublishedCache.PublishedContentCache.GetAtRoot(UmbracoContext umbracoContext, Boolean preview) at Umbraco.Web.PublishedCache.ContextualPublishedCache`1.GetAtRoot(Boolean preview) at Umbraco.Web.PublishedContentQuery.DocumentsAtRoot(ContextualPublishedCache cache) at MySiteName.MyNameSpace.common.GuideFunctions.GetCurrentSiteRootNodeID(UmbracoHelper umbracoHelper, String CurrentSiteURL) at MySiteName.MyNameSpace.verifyLicence()

On another note, should I be worried about this? "Failed to load Xml, file does not exist" which happened when I restarted the site, but the site does work properly:

2015-07-12 13:21:32,171 [50] INFO umbraco.content - [T22/D3] Load Xml from file... 2015-07-12 13:21:32,202 [50] WARN umbraco.content - [T22/D3] Failed to load Xml, file does not exist. 2015-07-12 13:21:32,202 [50] INFO umbraco.content - [T22/D3] Loading content from database... 2015-07-12 13:21:36,531 [50] INFO Umbraco.Core.PluginManager - [T22/D3] Starting resolution types of Umbraco.Core.Persistence.Mappers.BaseMapper 2015-07-12 13:21:36,531 [50] INFO Umbraco.Core.PluginManager - [T22/D3] Completed resolution of types of Umbraco.Core.Persistence.Mappers.BaseMapper, found 23 (took 1ms) 2015-07-12 13:21:37,015 [50] INFO Umbraco.Core.PluginManager - [T22/D3] Starting resolution types of Umbraco.Core.PropertyEditors.IParameterEditor 2015-07-12 13:21:37,015 [50] INFO Umbraco.Core.PluginManager - [T22/D3] Completed resolution of types of Umbraco.Core.PropertyEditors.IParameterEditor, found 45 (took 1ms) 2015-07-12 13:21:40,187 [50] INFO umbraco.content - [T33/D3] Save Xml to file... 2015-07-12 13:21:40,406 [50] INFO umbraco.content - [T6/D3] Saved Xml to file.

@schlubadub: which version? it can make a very big difference.

About the "file does not exist": that's expected due to the previous crash, and we recover by reloading from database, so nothing to worry about.

@zpqrtbnk Umbraco version 7.2.6 (assembly: 1.0.5632.22681)

Thanks for letting me know about the file not found item :)

If anyone cares, this appears to be resolved now using 7.2.8 (specifying the umbracoApplicationUrl)