From f708362313dfbe25a9afc6f7af96cb31449fcc72 Mon Sep 17 00:00:00 2001 From: Daniel Stolt Date: Tue, 28 Jul 2015 13:33:07 +0100 Subject: [PATCH] Made execution ID an ambient context property in recipe logging. --- src/Orchard.Web/Config/log4net.config | 3 +- .../Orchard.Recipes/Orchard.Recipes.csproj | 3 ++ .../RecipeExecutionStepHandler.cs | 2 +- .../Orchard.Recipes/Services/RecipeManager.cs | 30 ++++++++++++------- .../Services/RecipeScheduler.cs | 25 ++++++++++------ .../Services/RecipeStepExecutor.cs | 6 ++-- .../Services/RecipeStepQueue.cs | 6 ++-- 7 files changed, 46 insertions(+), 29 deletions(-) diff --git a/src/Orchard.Web/Config/log4net.config b/src/Orchard.Web/Config/log4net.config index 245cabf44..6ce6cf8f7 100644 --- a/src/Orchard.Web/Config/log4net.config +++ b/src/Orchard.Web/Config/log4net.config @@ -90,7 +90,6 @@ - @@ -101,7 +100,7 @@ - + diff --git a/src/Orchard.Web/Modules/Orchard.Recipes/Orchard.Recipes.csproj b/src/Orchard.Web/Modules/Orchard.Recipes/Orchard.Recipes.csproj index c43edbc48..21c46f0d1 100644 --- a/src/Orchard.Web/Modules/Orchard.Recipes/Orchard.Recipes.csproj +++ b/src/Orchard.Web/Modules/Orchard.Recipes/Orchard.Recipes.csproj @@ -51,6 +51,9 @@ ..\..\..\..\lib\autofac\Autofac.dll + + ..\..\..\..\lib\log4net\log4net.dll + diff --git a/src/Orchard.Web/Modules/Orchard.Recipes/Providers/RecipeHandlers/RecipeExecutionStepHandler.cs b/src/Orchard.Web/Modules/Orchard.Recipes/Providers/RecipeHandlers/RecipeExecutionStepHandler.cs index 7cb8bef34..b1d0edc61 100644 --- a/src/Orchard.Web/Modules/Orchard.Recipes/Providers/RecipeHandlers/RecipeExecutionStepHandler.cs +++ b/src/Orchard.Web/Modules/Orchard.Recipes/Providers/RecipeHandlers/RecipeExecutionStepHandler.cs @@ -19,7 +19,7 @@ namespace Orchard.Recipes.Providers.RecipeHandlers { var recipeExecutionContext = new RecipeExecutionContext {ExecutionId = recipeContext.ExecutionId, RecipeStep = recipeContext.RecipeStep}; if (executionStep != null) { - Logger.Information("Executing recipe step '{0}'; ExecutionId={1}", recipeContext.RecipeStep.Name, recipeContext.ExecutionId); + Logger.Information("Executing recipe step '{0}'.", recipeContext.RecipeStep.Name); executionStep.Execute(recipeExecutionContext); Logger.Information("Finished executing recipe step '{0}'.", recipeContext.RecipeStep.Name); recipeContext.Executed = true; diff --git a/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeManager.cs b/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeManager.cs index 2006364a4..7bc9a8d8f 100644 --- a/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeManager.cs +++ b/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeManager.cs @@ -1,5 +1,6 @@ using System; using System.Linq; +using log4net; using Orchard.Data; using Orchard.Logging; using Orchard.Recipes.Events; @@ -36,19 +37,26 @@ namespace Orchard.Recipes.Services { } var executionId = Guid.NewGuid().ToString("n"); - Logger.Information("Executing recipe '{0}' using ExecutionId {1}.", recipe.Name, executionId); - _recipeExecuteEventHandler.ExecutionStart(executionId, recipe); + ThreadContext.Properties["ExecutionId"] = executionId; - foreach (var recipeStep in recipe.RecipeSteps) { - _recipeStepQueue.Enqueue(executionId, recipeStep); - _recipeStepResultRecordRepository.Create(new RecipeStepResultRecord() { - ExecutionId = executionId, - StepName = recipeStep.Name - }); + try { + Logger.Information("Executing recipe '{0}'.", recipe.Name); + _recipeExecuteEventHandler.ExecutionStart(executionId, recipe); + + foreach (var recipeStep in recipe.RecipeSteps) { + _recipeStepQueue.Enqueue(executionId, recipeStep); + _recipeStepResultRecordRepository.Create(new RecipeStepResultRecord() { + ExecutionId = executionId, + StepName = recipeStep.Name + }); + } + _recipeScheduler.ScheduleWork(executionId); + + return executionId; + } + finally { + ThreadContext.Properties["ExecutionId"] = null; } - _recipeScheduler.ScheduleWork(executionId); - - return executionId; } } } \ No newline at end of file diff --git a/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeScheduler.cs b/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeScheduler.cs index 9d9ff8427..9244b86e9 100644 --- a/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeScheduler.cs +++ b/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeScheduler.cs @@ -1,5 +1,6 @@ using System; using System.Collections.Generic; +using log4net; using Orchard.Environment.Configuration; using Orchard.Environment.Descriptor; using Orchard.Environment.State; @@ -42,15 +43,21 @@ namespace Orchard.Recipes.Services { } public void ExecuteWork(string executionId) { - Logger.Information("Executing next step of recipe {0}.", executionId); - // todo: this callback should be guarded against concurrency by the IProcessingEngine - var scheduleMore = _recipeStepExecutor.Value.ExecuteNextStep(executionId); - if (scheduleMore) - ScheduleWork(executionId); - else - // https://github.com/OrchardCMS/Orchard/issues/3672 - // Because recipes execute in their own workcontext, we need to restart the shell, as signaling a cache won't work across workcontexts. - _events.Changed(_shellDescriptorManager.GetShellDescriptor(), _shellSettings.Name); + ThreadContext.Properties["ExecutionId"] = executionId; + try { + Logger.Information("Executing next step of recipe."); + // todo: this callback should be guarded against concurrency by the IProcessingEngine + var scheduleMore = _recipeStepExecutor.Value.ExecuteNextStep(executionId); + if (scheduleMore) + ScheduleWork(executionId); + else + // https://github.com/OrchardCMS/Orchard/issues/3672 + // Because recipes execute in their own workcontext, we need to restart the shell, as signaling a cache won't work across workcontexts. + _events.Changed(_shellDescriptorManager.GetShellDescriptor(), _shellSettings.Name); + } + finally { + ThreadContext.Properties["ExecutionId"] = null; + } } } } \ No newline at end of file diff --git a/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeStepExecutor.cs b/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeStepExecutor.cs index 7d1ad2ae0..6f6c94618 100644 --- a/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeStepExecutor.cs +++ b/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeStepExecutor.cs @@ -28,7 +28,7 @@ namespace Orchard.Recipes.Services { public bool ExecuteNextStep(string executionId) { var nextRecipeStep = _recipeStepQueue.Dequeue(executionId); if (nextRecipeStep == null) { - Logger.Information("Recipe execution {0} completed.", executionId); + Logger.Information("Recipe execution completed."); _recipeExecuteEventHandler.ExecutionComplete(executionId); return false; } @@ -49,14 +49,14 @@ namespace Orchard.Recipes.Services { } catch (Exception ex) { UpdateStepResultRecord(executionId, nextRecipeStep.Name, isSuccessful: false, errorMessage: ex.Message); - Logger.Error(ex, "Recipe execution {0} failed because the step '{1}' failed.", executionId, nextRecipeStep.Name); + Logger.Error(ex, "Recipe execution failed because the step '{0}' failed.", nextRecipeStep.Name); while (_recipeStepQueue.Dequeue(executionId) != null); var message = T("Recipe execution with ID {0} failed because the step '{1}' failed to execute. The following exception was thrown:\n{2}\nRefer to the error logs for more information.", executionId, nextRecipeStep.Name, ex.Message); throw new OrchardCoreException(message); } if (!recipeContext.Executed) { - Logger.Error("Recipe execution {0} failed because no matching handler for recipe step '{1}' was found.", executionId, recipeContext.RecipeStep.Name); + Logger.Error("Recipe execution failed because no matching handler for recipe step '{0}' was found.", recipeContext.RecipeStep.Name); while (_recipeStepQueue.Dequeue(executionId) != null); var message = T("Recipe execution with ID {0} failed because no matching handler for recipe step '{1}' was found. Refer to the error logs for more information.", executionId, nextRecipeStep.Name); throw new OrchardCoreException(message); diff --git a/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeStepQueue.cs b/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeStepQueue.cs index 35e7df4d1..c34b3c70d 100644 --- a/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeStepQueue.cs +++ b/src/Orchard.Web/Modules/Orchard.Recipes/Services/RecipeStepQueue.cs @@ -23,7 +23,7 @@ namespace Orchard.Recipes.Services { public ILogger Logger { get; set; } public void Enqueue(string executionId, RecipeStep step) { - Logger.Information("Enqueuing step '{0}' for recipe {1}.", step.Name, executionId); + Logger.Information("Enqueuing recipe step '{0}'.", step.Name); var recipeStepElement = new XElement("RecipeStep"); recipeStepElement.Add(new XElement("Name", step.Name)); recipeStepElement.Add(step.Step); @@ -41,7 +41,7 @@ namespace Orchard.Recipes.Services { } public RecipeStep Dequeue(string executionId) { - Logger.Information("Dequeuing steps for recipe {0}.", executionId); + Logger.Information("Dequeuing recipe steps."); if (!_appDataFolder.DirectoryExists(Path.Combine(_recipeQueueFolder, executionId))) { return null; } @@ -52,7 +52,7 @@ namespace Orchard.Recipes.Services { // string to xelement var stepElement = XElement.Parse(_appDataFolder.ReadFile(stepPath)); var stepName = stepElement.Element("Name").Value; - Logger.Information("Dequeuing step '{0}' for recipe {1}.", stepName, executionId); + Logger.Information("Dequeuing recipe step '{0}'.", stepName); recipeStep = new RecipeStep { Name = stepName, Step = stepElement.Element(stepName)