search

umbraco / Umbraco-CMS

Umbraco is a free and open source .NET content management system helping you deliver delightful digital experiences.
https://umbraco.com
MIT License
4.5k stars 2.69k forks source link

Custom index fields disappearing #6123

Closed ModerModemet closed 4 years ago

ModerModemet commented 5 years ago

Please, can somebody help!

We're running Umbraco v8.1.1 deployed to an Azure Web App.

We're adding custom fields to the ExternalIndex by hooking up to the TransformingIndexValues event (code is shown further down).

After the site has been running for a while and server goes to sleep or some kind of swapping occurs (can't determine exactly what triggers it and don't know exactly how Azure works), Umbraco triggers a reindexing but not all nodes gets their custom fields added.

Sometimes some of the nodes retains the custom fields, while others not. Sometimes all nodes lose the custom fields.

When we publish nodes or trigger reindexing from the Examine Management in backoffice, custom fields are always added to all nodes.

Web.config

We've added two settings to the web.config under the \ tag:

Umbraco.Core.LocalTempStorage

\

Umbraco.Examine.LuceneDirectoryFactory

\<add key="Umbraco.Examine.LuceneDirectoryFactory" value="Examine.LuceneEngine.Directories.TempEnvDirectoryFactory,Examine"/ OR \ (we've tried both)

Composer and TransformingIndexValues

public class SearchInitializationComposer
    : ComponentComposer<SearchInitializationComponent>, IUserComposer
{
}

public class SearchInitializationComponent : IComponent
{
    private readonly IExamineManager _examineManager;
    private readonly IContentService _contentService;
    private readonly IMediaService _mediaService;
    private readonly ILogger _logger;

    public SearchInitializationComponent(IExamineManager examineManager, IContentService contentService, IMediaService mediaService, ILogger logger)
    {
        this._examineManager = examineManager;
        this._contentService = contentService;
        this._mediaService = mediaService;
        this._logger = logger;
    }

    public void Initialize()
    {
        this._logger.Info<SearchInitializationComposer>("Initialize start");

        if (!this._examineManager.TryGetIndex("ExternalIndex", out IIndex index))
        {
            throw new InvalidOperationException("No index found by name ExternalIndex");
        }

        if (!(index is BaseIndexProvider indexProvider))
        {
            throw new InvalidOperationException("Could not cast");
        }

        indexProvider.TransformingIndexValues += this.ExternalIndex_TransformingIndexValues;

        this._logger.Info<SearchInitializationComposer>("Initialize end");
    }

    public void Terminate()
    {
    }

    private void ExternalIndex_TransformingIndexValues(object sender, IndexingItemEventArgs e)
    {
        switch (e.ValueSet.Category)
        {
            case IndexTypes.Content:
                {
                    IContent content = this._contentService.GetById(Convert.ToInt32(e.ValueSet.Id));

                    e.ValueSet.Values.Add("_fulltext", new List<object> { CombineFields(content, new List<string> { "heading", "answer", "preamble", "mainGrid", }) });

                    break;
                }

            case IndexTypes.Media:
                {
                    break;
                }
        }
    }
}

Composer RuntimeLevel

We've tried inheriting the Composer from ICoreComposer instead of IUserComposer to see if hooking up the the events earlier in the boot process makes any difference. Unfortunately, when using ICoreComposer the _examineManager.TryGetIndex("ExternalIndex", out IIndex index) fails to find ExternalIndex (fails on Azure, works locally). So this doesn't seem to be an option.

Log during boot and 30 min further on Azure

{"@t":"2019-08-14T04:05:35.8621208Z","@mt":"{StartMessage} [Timing {TimingId}]","StartMessage":"Booting Umbraco 8.1.1.","TimingId":"5dc1836","SourceContext":"Umbraco.Core.Runtime.CoreRuntime","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:35.9070320Z","@mt":"Booting site '{HostingSiteName}', app '{HostingApplicationID}', path '{HostingPhysicalPath}', server '{MachineName}'.","HostingSiteName":"xxx","HostingApplicationID":"/LM/W3SVC/857868861/ROOT","HostingPhysicalPath":"D:\\home\\site\\wwwroot\\","MachineName":"RD0003FF76F2D4","SourceContext":"Umbraco.Core.Runtime.CoreRuntime","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:36.1726739Z","@mt":"Acquiring.","SourceContext":"Umbraco.Core.MainDom","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:36.1726739Z","@mt":"Acquired.","SourceContext":"Umbraco.Core.MainDom","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:38.0320147Z","@mt":"{StartMessage} [Timing {TimingId}]","StartMessage":"Resolving composer types.","TimingId":"106b98e","SourceContext":"Umbraco.Core.Runtime.CoreRuntime","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:42.2509584Z","@mt":"{EndMessage} ({Duration}ms) [Timing {TimingId}]","EndMessage":"Resolved.","Duration":4228,"TimingId":"106b98e","SourceContext":"Umbraco.Core.Runtime.CoreRuntime","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:47.6414347Z","@mt":"Profiler is VoidProfiler, not profiling (must run debug mode to profile).","SourceContext":"Umbraco.Web.Logging.WebProfilerComponent","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:47.9852120Z","@mt":"Initializing Umbraco internal event handlers for cache refreshing.","SourceContext":"Umbraco.Web.Cache.DistributedCacheBinderComponent","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:48.1101923Z","@mt":"Adding examine event handlers for {RegisteredIndexers} index providers.","RegisteredIndexers":3,"SourceContext":"Umbraco.Web.Search.ExamineComponent","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:48.1258183Z","@mt":"Starting initialize async background thread.","SourceContext":"Umbraco.Web.Search.ExamineComponent","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:48.1883059Z","@mt":"No last synced Id found, this generally means this is a new server/install. The server will build its caches and indexes, and then adjust its last synced Id to the latest found in the database and maintain cache updates based on that Id.","@l":"Warning","SourceContext":"Umbraco.Core.Sync.DatabaseServerMessenger","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"WARN ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:48.3601965Z","@mt":"Call was made to RebuildIndexes but the task runner for rebuilding is already running","@l":"Warning","SourceContext":"Umbraco.Web.Search.ExamineComponent","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"WARN ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:48.4070976Z","@mt":"Running Import: {0}","0":"Languages","SourceContext":"uSync8.BackOffice.uSync8BackOffice","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:48.5008326Z","@mt":"Running Import: {0}","0":"DataTypes","SourceContext":"uSync8.BackOffice.uSync8BackOffice","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:50.2352279Z","@mt":"Running Import: {0}","0":"Templates","SourceContext":"uSync8.BackOffice.uSync8BackOffice","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:51.2196212Z","@mt":"Running Import: {0}","0":"ContentTypes","SourceContext":"uSync8.BackOffice.uSync8BackOffice","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:56.3915161Z","@mt":"Running Import: {0}","0":"MediaTypes","SourceContext":"uSync8.BackOffice.uSync8BackOffice","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:56.4389454Z","@mt":"Running Import: {0}","0":"MemberTypes","SourceContext":"uSync8.BackOffice.uSync8BackOffice","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:56.4758182Z","@mt":"Running Import: {0}","0":"Macros","SourceContext":"uSync8.BackOffice.uSync8BackOffice","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:56.5477488Z","@mt":"Initialize start","SourceContext":"xxx.Web.Infrastructure.Initialization.SearchInitializationComposer","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:56.5477488Z","@mt":"Initialize end","SourceContext":"xxx.Web.Infrastructure.Initialization.SearchInitializationComposer","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:56.6571389Z","@mt":"{EndMessage} ({Duration}ms) [Timing {TimingId}]","EndMessage":"Booted.","Duration":20820,"TimingId":"5dc1836","SourceContext":"Umbraco.Core.Runtime.CoreRuntime","ProcessId":21868,"ProcessName":"w3wp","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"dc5a1637-78d3-45af-be4b-d0f882cd1dc4"}
{"@t":"2019-08-14T04:05:58.7977612Z","@mt":"New url {Url} detected, re-discovering application url.","Url":"http://xxx.azurewebsites.net:80/umbraco","SourceContext":"Umbraco.Core.Sync.ApplicationUrlHelper","ProcessId":21868,"ProcessName":"w3wp","ThreadId":15,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":2,"HttpRequestId":"ad659cd2-55ee-4786-8fe5-669182df3023"}
{"@t":"2019-08-14T04:05:58.7977612Z","@mt":"ApplicationUrl: {UmbracoAppUrl} (UmbracoModule request)","UmbracoAppUrl":"http://xxx.azurewebsites.net:80/umbraco","SourceContext":"Umbraco.Core.Sync.ApplicationUrlHelper","ProcessId":21868,"ProcessName":"w3wp","ThreadId":15,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":2,"HttpRequestId":"ad659cd2-55ee-4786-8fe5-669182df3023"}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Scheduled health check results:","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' all completed successfully.","HealthCheckName":"Folder & File Permissions","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Folder & File Permissions","HealthCheckResult":"Success","HealthCheckMessage":"All folders have the correct permissions set.","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Folder & File Permissions","HealthCheckResult":"Success","HealthCheckMessage":"All files have the correct permissions set.","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' all completed successfully.","HealthCheckName":"SMTP Settings","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"SMTP Settings","HealthCheckResult":"Success","HealthCheckMessage":"SMTP settings are configured correctly and the service is operating as expected.","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' all completed successfully.","HealthCheckName":"Macro errors","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Macro errors","HealthCheckResult":"Success","HealthCheckMessage":"MacroErrors are set to 'inline'.","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' all completed successfully.","HealthCheckName":"Notification Email Settings","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Notification Email Settings","HealthCheckResult":"Success","HealthCheckMessage":"Notification email has been set to <strong>Fastighetsmäklarinspektionen <registrator@xxx.se></strong>.","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' all completed successfully.","HealthCheckName":"Try Skip IIS Custom Errors","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Try Skip IIS Custom Errors","HealthCheckResult":"Success","HealthCheckMessage":"Try Skip IIS Custom Errors is set to 'true' and you're using IIS version '10.0'.","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' completed with errors.","@l":"Warning","HealthCheckName":"Custom Errors","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"WARN "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Custom Errors","HealthCheckResult":"Error","HealthCheckMessage":"Custom errors are currently set to 'Off'. It is recommended to set this to 'RemoteOnly' before go live.","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' all completed successfully.","HealthCheckName":"Trace Mode","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Trace Mode","HealthCheckResult":"Success","HealthCheckMessage":"Trace mode is disabled.","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' all completed successfully.","HealthCheckName":"Debug Compilation Mode","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Debug Compilation Mode","HealthCheckResult":"Success","HealthCheckMessage":"Debug compilation mode is disabled.","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' completed with errors.","@l":"Warning","HealthCheckName":"Cross-site scripting Protection (X-XSS-Protection header)","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"WARN "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Cross-site scripting Protection (X-XSS-Protection header)","HealthCheckResult":"Error","HealthCheckMessage":"Error pinging the URL http://xxx.azurewebsites.net/umbraco - 'The remote server returned an error: (403) Forbidden.'","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' completed with errors.","@l":"Warning","HealthCheckName":"Cookie hijacking and protocol downgrade attacks Protection (Strict-Transport-Security Header (HSTS))","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"WARN "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Cookie hijacking and protocol downgrade attacks Protection (Strict-Transport-Security Header (HSTS))","HealthCheckResult":"Error","HealthCheckMessage":"Error pinging the URL http://xxx.azurewebsites.net/umbraco - 'The remote server returned an error: (403) Forbidden.'","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' completed with errors.","@l":"Warning","HealthCheckName":"Content/MIME Sniffing Protection","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"WARN "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Content/MIME Sniffing Protection","HealthCheckResult":"Error","HealthCheckMessage":"Error pinging the URL http://xxx.azurewebsites.net/umbraco - 'The remote server returned an error: (403) Forbidden.'","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' completed with errors.","@l":"Warning","HealthCheckName":"Excessive Headers","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"WARN "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Excessive Headers","HealthCheckResult":"Warning","HealthCheckMessage":"[httpsCheckInvalidUrl]","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' completed with errors.","@l":"Warning","HealthCheckName":"Click-Jacking Protection","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"WARN "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"Click-Jacking Protection","HealthCheckResult":"Error","HealthCheckMessage":"Error pinging the URL http://xxx.azurewebsites.net/umbraco - 'The remote server returned an error: (403) Forbidden.'","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Checks for '{HealthCheckName}' completed with errors.","@l":"Warning","HealthCheckName":"HTTPS Configuration","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"WARN "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"HTTPS Configuration","HealthCheckResult":"Error","HealthCheckMessage":"You are currently not viewing the site using the HTTPS scheme.","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"HTTPS Configuration","HealthCheckResult":"Info","HealthCheckMessage":"The appSetting 'Umbraco.Core.UseHttps' is set to 'false' in your web.config file. Once you access this site using the HTTPS scheme, that should be set to 'true'.","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:06:59.9393923Z","@mt":"Result for {HealthCheckName}: {HealthCheckResult}, Message: '{HealthCheckMessage}'","HealthCheckName":"HTTPS Configuration","HealthCheckResult":"Error","HealthCheckMessage":"Error pinging the URL https://xxx.azurewebsites.net/umbraco - 'The remote server returned an error: (403) Forbidden.'","SourceContext":"Umbraco.Web.HealthCheck.HealthCheckResults","ProcessId":21868,"ProcessName":"w3wp","ThreadId":12,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9680603Z","@mt":"{LogPrefix} Terminating {Immediate}","LogPrefix":"[RebuildIndexesOnStartup] ","Immediate":"","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9680603Z","@mt":"{LogPrefix} Waiting for tasks to complete","LogPrefix":"[RebuildIndexesOnStartup] ","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9876055Z","@mt":"{LogPrefix} Tasks {TaskStatus}, terminated","LogPrefix":"[RebuildIndexesOnStartup] ","TaskStatus":"completed","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9876055Z","@mt":"{LogPrefix} Terminating {Immediate}","LogPrefix":"[ServerInstProcess] ","Immediate":"","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9876055Z","@mt":"{LogPrefix} Waiting for tasks to complete","LogPrefix":"[ServerInstProcess] ","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9876055Z","@mt":"{LogPrefix} Terminating {Immediate}","LogPrefix":"[HealthCheckNotifier] ","Immediate":"","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9876055Z","@mt":"{LogPrefix} Waiting for tasks to complete","LogPrefix":"[HealthCheckNotifier] ","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9876055Z","@mt":"{LogPrefix} Terminating {Immediate}","LogPrefix":"[ScheduledPublishing] ","Immediate":"","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9876055Z","@mt":"{LogPrefix} Waiting for tasks to complete","LogPrefix":"[ScheduledPublishing] ","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9997542Z","@mt":"Stopping ({SignalSource})","SignalSource":"environment","SourceContext":"Umbraco.Core.MainDom","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9997542Z","@mt":"{LogPrefix} Tasks {TaskStatus}, terminated","LogPrefix":"[ServerInstProcess] ","TaskStatus":"completed","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":5,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9997542Z","@mt":"{LogPrefix} Tasks {TaskStatus}, terminated","LogPrefix":"[ScheduledPublishing] ","TaskStatus":"completed","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":5,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:29.9997542Z","@mt":"{LogPrefix} Tasks {TaskStatus}, terminated","LogPrefix":"[HealthCheckNotifier] ","TaskStatus":"completed","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":16,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0467502Z","@mt":"{StartMessage} [Timing {TimingId}]","StartMessage":"Examine shutting down","TimingId":"b697d45","SourceContext":"Umbraco.Web.Search.ExamineComponent","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0651246Z","@mt":"{EndMessage} ({Duration}ms) [Timing {TimingId}]","EndMessage":"Completed.","Duration":18,"TimingId":"b697d45","SourceContext":"Umbraco.Web.Search.ExamineComponent","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"Released ({SignalSource})","SignalSource":"environment","SourceContext":"Umbraco.Core.MainDom","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Terminating {Immediate}","LogPrefix":"[LogScrubber] ","Immediate":"","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Waiting for tasks to complete","LogPrefix":"[LogScrubber] ","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Terminating {Immediate}","LogPrefix":"[ScheduledTasks] ","Immediate":"","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Waiting for tasks to complete","LogPrefix":"[ScheduledTasks] ","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Tasks {TaskStatus}, terminated","LogPrefix":"[ScheduledTasks] ","TaskStatus":"completed","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Terminating {Immediate}","LogPrefix":"[KeepAlive] ","Immediate":"","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Waiting for tasks to complete","LogPrefix":"[KeepAlive] ","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Terminating {Immediate}","LogPrefix":"[ServerRegistration] ","Immediate":"","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Waiting for tasks to complete","LogPrefix":"[ServerRegistration] ","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":53,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Tasks {TaskStatus}, terminated","LogPrefix":"[KeepAlive] ","TaskStatus":"completed","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":84,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Tasks {TaskStatus}, terminated","LogPrefix":"[LogScrubber] ","TaskStatus":"completed","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":62,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T04:33:30.0773904Z","@mt":"{LogPrefix} Tasks {TaskStatus}, terminated","LogPrefix":"[ServerRegistration] ","TaskStatus":"completed","SourceContext":"Umbraco.Web.Scheduling.BackgroundTaskRunner","ProcessId":21868,"ProcessName":"w3wp","ThreadId":56,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
nul800sebastiaan commented 5 years ago

Hi @Allemannen - that sounds pretty annoying! I'll check with the team if there's any obvious configurations that are missing or wrong. In the mean time, you write:

Sometimes some of the nodes retains the custom fields, while others not. Sometimes all nodes lose the custom fields.

Do you have logs from when some or all of the fields went missing? What does it mean they are missing, are they just not in the index (and how do you check this)? Is there a common theme to the missing fields, for example do they all store JSON data or something else maybe?

ModerModemet commented 5 years ago

Hi @nul800sebastiaan - thank you very much for replying!

How the fields are missing

We inspect a node in the backoffice Examine Management, and all custom fields on that node are gone. In other words, the field value is not empty, the field simple doesn't exist. Though, the same field can exist on another node where the problem didn't occur, and either have a value or empty value depending on if there was any info that should be indexed. We've also built Examine search queries that rely on searching those custom fields, and those return no results on those nodes missing the custom fields. I havent used any other software to inspect the index.

RebuildIndexesOnStartup TransformingIndexValues

Does Umbraco ensure that TransformingIndexValues events added via IUserComposer always have been attached before any form of automatic indexing occur on startup? Could it be the case that the programming logic executes kind of like a race condition, and everything works great until some other thread happens to be slower. Some things can be slower to initialize on Azure due to their infrastructure.

Possible pattern

So far it has only occured once that all nodes lost all custom fields. The most frequent scenario is that only some nodes lose custom fields. When that happens, there seems indeed to be a pattern. All pages consist of 3 document types, where all pages of those 3 document types have lost their custom fields. Important to note is that I can't really determine if that is a true causation between cause and effect. It could just be that the pages with those 3 document types happens to arrive in a succesive order when the index job fetches all nodes to index, or some other obscure coincidence. Because I cannot for the life of me find any indication why those 3 document types should be different. I cant find that any of them has any unique property, or unique data to be indexed that the other document types don't have.

Sidenote, but strange: index reports rebuilds 3 times

When looking through the log after I manual reindexed from backoffice Examine Management. Might not be important, because in this scenario everyhing always works as it should. I also remember when debugging that my breakpoint hit multiple times inside TransformingIndexValues for the same node, which I found strange. Just wanted to mention it because I'm desperately grasping for clues.

{"@t":"2019-08-14T06:02:01.9280522Z","@mt":"Rebuilding index '{IndexName}'","IndexName":"ExternalIndex","SourceContext":"Umbraco.Web.Editors.ExamineManagementController","ProcessId":12712,"ProcessName":"w3wp","ThreadId":27,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO ","HttpRequestNumber":5,"HttpRequestId":"48154499-587c-4d9b-a109-cbe7e5c02d6b"}
{"@t":"2019-08-14T06:02:04.1039447Z","@mt":"Rebuilding index 'ExternalIndex' done, 122 items committed (can differ from the number of items in the index)","SourceContext":"Umbraco.Web.Editors.ExamineManagementController","ProcessId":12712,"ProcessName":"w3wp","ThreadId":38,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T06:02:04.1039447Z","@mt":"Rebuilding index 'ExternalIndex' done, 122 items committed (can differ from the number of items in the index)","SourceContext":"Umbraco.Web.Editors.ExamineManagementController","ProcessId":12712,"ProcessName":"w3wp","ThreadId":44,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}
{"@t":"2019-08-14T06:02:04.1039447Z","@mt":"Rebuilding index 'ExternalIndex' done, 122 items committed (can differ from the number of items in the index)","SourceContext":"Umbraco.Web.Editors.ExamineManagementController","ProcessId":12712,"ProcessName":"w3wp","ThreadId":30,"AppDomainId":2,"AppDomainAppId":"LMW3SVC857868861ROOT","MachineName":"RD0003FF76F2D4","Log4NetLevel":"INFO "}

Other log files

It's hard to get log files, because the problem occur when I'm not actively using the site, since it has something to do when Azure server wakes up. Other people are visiting the site to test stuff, so it's hard to know if they previously have triggered the failure, and when that happened. I think the problem occurred in the log I attached in my first entry. I'll to try to reproduce the problem in a more controlled manner, to be sure to get 100% solid log.

ModerModemet commented 5 years ago

After monitoring the site a couple of days its become clear that eventually after a couple of sleep/boot cycles all nodes lose their custom fields, even media (images, files).

Please is it possible to fix this in the source code?

Shazwazza commented 5 years ago

Hi, I'd recommend updating to 8.1.2 there is a couple things in there that fixes/changes some Examine indexing issues, https://our.umbraco.com/download/releases//812

There was a timing issue which is fixed.

When using SyncTempEnvDirectoryFactory, indexes should not 'just' rebuild out of nowhere because when using this setting the 'master' index files are located on the 'slow drive' in azure (over the network) and synced to the 'fast drive' (local to the server). But perhaps if you are slot swapping or something like that, then this could occur.

Rebuilding on startup when no indexes are found is performed on a background thread a few seconds after startup occurs, so in theory your even handlers should be bound before that occurs even before the fixes in 8.1.2.... but i guess stranger things have happened.

I'd recommend adding an info/debug log on your TransformingIndexValues call so that you definitely know it's executing and upgrading to 8.1.2 and see how you go. You should stick to using IUserComposer.

Sidenote, but strange: index reports rebuilds 3 times

Yep i can replicate, i'll open a new issue for that. It's not causing any problems but should be reported correctly. The issue is that on an index rebuild we listen for the IndexOperationComplete but then we populate the index based on all of the 'populators' which means that there a several index operations performed to rebuild an index.

remkovb commented 4 years ago

We are experiencing exactly the same in our current Umbraco 8.6.2 website. So long after the 8.1.2 release... How is this possible?

We are simply adding custom field values for some mntps because of lucene queries we do based on that properties.

When for example doing a change in umbracosettings.config all of a sudden the custom fields are gone. After just doing a general search on our website the examine index is back the way it was (including the custom fields)

This is a really annoying bug that already has taken us days to debug without any success. Hopefuly there already is a solution for this?

Shazwazza commented 4 years ago

@remkovb can you provide basic steps to replicate from a vanilla umbraco install?

nul800sebastiaan commented 4 years ago

@remkovb Do you have any custom indexes? Or have you customized the indexes? It sound like the same problem as here: https://github.com/umbraco/Umbraco-CMS/issues/8766

remkovb commented 4 years ago

Steps to reproduce:

  1. Create one document type for example Theme with no properties
  2. Create another documenttype Article with multinode tree picker for Theme (multiple nodes allowed), with alias "themes"
  3. Add some themes and some articles and select some themes
  4. Add Composer:
[RuntimeLevel(MinLevel = RuntimeLevel.Run)]
public class UmbracoCustomComposer : IUserComposer 
    {
        public void Compose(Composition composition)
        {
            composition.Components().Append<RegisterExamineEventsComponent>();       
        }
    }

  1. Add component:

    public class RegisterExamineEventsComponent : Umbraco.Core.Composing.IComponent
{
    private readonly IExamineManager _examineManager;
    private readonly IContentService _contentService;

    public RegisterExamineEventsComponent(IExamineManager examineManager, IContentService contentService)
    {
        _examineManager = examineManager;
        _contentService = contentService;
    }

    public void Initialize()
    {
        var externalIndex = _examineManager?.Indexes?.FirstOrDefault(f => f.Name == "ExternalIndex");
        if (externalIndex != null)
        {
            ((BaseIndexProvider)externalIndex).TransformingIndexValues += RegisterExamineEventsComponent_TransformingIndexValues;
        }
    }

    private void RegisterExamineEventsComponent_TransformingIndexValues(object sender, IndexingItemEventArgs e)
    {
        int nodeId = e?.ValueSet?.Id?.To<int>() ?? 0;
        IContent theNode = nodeId > 0 ? _contentService?.GetById(nodeId) : null;      

        if (theNode != null)
        {
            var themesValue = e.ValueSet.Values.Where(x => x.Key == "themes").Select(x => x.Value).FirstOrDefault();     

            if(themesValue != null)
            {           
              var themesValueRewritten = themesValue.First().ToString().Replace(",", " ");

              var themesList = new List<object>();
              themesList.Add(themesValueRewritten);

              e.ValueSet.Values.Add("__themes", themesList);
            }
        }
    }
}
  2. Republish article nodes and see __themes being added
  3. Do Examine search like: __themes:("umb document/a5eac17e7f9940d682d3a1b24ce88263") : results appear
  4. Change something in umbracosettings.config
  5. Search again with examine (in backoffice) and no results appear...
remkovb commented 4 years ago

@remkovb Do you have any custom indexes? Or have you customized the indexes? It sound like the same problem as here: #8766

No just adding simple rewrite of mntp (comma to whitespace) on ExternalIndex

remkovb commented 4 years ago

Update on my side... really strange behaviour, but maybe not for you guys..

The field seems to be there, but this query doesn't seem to give results, like I said: __themes:("umb document/a5eac17e7f9940d682d3a1b24ce88263")

But when we use this query, it gives results actually.. __themes:("a5eac17e7f9940d682d3a1b24ce88263")

So query on UDI seems to go wrong somehow?

Shazwazza commented 4 years ago

Yes a query on UDI directly won't work because it contains a ":" which is a lucene char. To query a UDI it will need to be a custom analyzer/field type or it could be escaped. Understanding Lucene analyzers is important, depending on the one used will yield very different results, many special chars will be stripped out, etc... You can try to escape a UDI, this can be done with the Examine fluent API or if you are using NativeQuery then you need to use the lucene api to escape a string... but off the top of my head I'm not 100% that will work without a custom analyzer - for that field you could try using a whitespace analyzer and then escape the value.

nul800sebastiaan commented 4 years ago

But you still have a problem with disappearing custom fields when the app pool recycles, or..?

remkovb commented 4 years ago

Well actually, by doing the queries and looking at fields in Examine tab I found out the field was actually there.

But somehow this: (generated with fluent api actually) __themes:("umb document/a5eac17e7f9940d682d3a1b24ce88263")

Normally works, but sometimes not, after reboot. When doing reindex of simply use search function on site the query above does return results.. Always use to query this way with udi's so don't really know why this is.

But after doing research, just using Key.Replace("-", "") always returns desired results, also after reboot: __themes:("a5eac17e7f9940d682d3a1b24ce88263")

So there is something in the background that makes udi's unsearchable after reboot or something? We now use the work-around to simply use Key as search argument. But still curious what's the cause ;-)

nul800sebastiaan commented 4 years ago

I've just done a few simple tests using your code and I can't reproduce the problem even after rebooting the site every way I can think of.

Here's my razor to do the query:

    if (ExamineManager.Instance.TryGetIndex("ExternalIndex", out var index2))
    {
        var searcher = index2.GetSearcher();
        var results = searcher.CreateQuery("content").Field("myThemes", "umb document/ca4249ed2b234337b52263cabe5587d1").Execute();
        if (results.Any())
        {
            <h1>Results!</h1>
            foreach (var r in results)
            {
                <p>@r.Id</p>
            }
        }
    }

I have not use the ___ notation in my fieldname, that really should only be used for system fields as far as I know. My mntp values get converted correctly and stored in the myThemes field and querying one works every time.

Mind you, I'm running on the 8.8 RC source code, but don't think anything has changed between 8.6.2 and 8.8.0. So maybe it's the underscores prefix?

If you can still reproduce then I recommend:

namespace Testing { [RuntimeLevel(MinLevel = RuntimeLevel.Run)] public class UmbracoCustomComposer : IUserComposer { public void Compose(Composition composition) { composition.Components().Append(); } }

public class RegisterExamineEventsComponent : Umbraco.Core.Composing.IComponent
{
    private readonly IExamineManager _examineManager;
    private readonly IContentService _contentService;

    public RegisterExamineEventsComponent(IExamineManager examineManager, IContentService contentService)
    {
        _examineManager = examineManager;
        _contentService = contentService;
    }

    public void Initialize()
    {
        var externalIndex = _examineManager?.Indexes?.FirstOrDefault(f => f.Name == "ExternalIndex");
        if (externalIndex != null)
        {
            ((BaseIndexProvider)externalIndex).TransformingIndexValues += RegisterExamineEventsComponent_TransformingIndexValues;
        }
    }

    public void Terminate()
    {
        throw new System.NotImplementedException();
    }

    private void RegisterExamineEventsComponent_TransformingIndexValues(object sender, IndexingItemEventArgs e)
    {
        int nodeId = int.Parse(e.ValueSet.Id);
        IContent theNode = nodeId > 0 ? _contentService?.GetById(nodeId) : null;

        if (theNode != null)
        {
            var themesValue = e.ValueSet.Values.Where(x => x.Key == "themers").Select(x => x.Value).FirstOrDefault();

            if(themesValue != null)
            {
                var themesValueRewritten = themesValue.First().ToString().Replace(",", " ");

                var themesList = new List<object>();
                themesList.Add(themesValueRewritten);

                e.ValueSet.Values.Add("myThemes", themesList);
            }
        }
    }
}

}


- Reproduce the problem 
- If you can repro then zip the whole thing up and send it to us - including the username/pass to get into the backoffice please.

I'll close this issue for now since it's unfortunately not something that can be reproduced at the moment. Happy to have another look if you get it to fail on a clean install of course. Happy you have a workaround for now at least!
remkovb commented 4 years ago

Thanks Sebastiaan and Shannon!

Great you guys are able to help me and look into this. Hopefuly I'll have the time to reproduce it next week. I'll let you know.