Made execution ID an ambient context property in recipe logging.

src/Orchard.Web/Config/log4net.config

@@ -90,7 +90,6 @@
     </appender>
 
     <appender name="recipes-file" type="Orchard.Logging.OrchardFileAppender">
-        <!-- Sends ERROR and FATAL log messages to a file in App_Data. -->
         <file value="App_Data/Logs/orchard-recipes" />
         <appendToFile value="true" />
         <!-- Immediate flush on error log, to avoid data loss with sudden termination. -->
@@ -101,7 +100,7 @@
         <!-- Prevents Orchard.exe from displaying locking debug messages. -->
         <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
         <layout type="log4net.Layout.PatternLayout">
-            <conversionPattern value="%date [%thread] %logger - %P{Tenant} - %level% %message%newline" />
+            <conversionPattern value="%date %logger - %P{Tenant} - %level% %message [ExecutionId=%P{ExecutionId}]%newline" />
         </layout>
     </appender>
 

src/Orchard.Web/Modules/Orchard.Recipes/Orchard.Recipes.csproj

@@ -51,6 +51,9 @@
     <Reference Include="Autofac">
       <HintPath>..\..\..\..\lib\autofac\Autofac.dll</HintPath>
     </Reference>
+    <Reference Include="log4net">
+      <HintPath>..\..\..\..\lib\log4net\log4net.dll</HintPath>
+    </Reference>
     <Reference Include="Microsoft.CSharp" />
     <Reference Include="System" />
     <Reference Include="System.Data.DataSetExtensions" />

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;

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;
         }
     }
 }

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;
+            }
         }
     }
 }

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);

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)