SED-3086 automation-package-and-assertion-plan-execution-stability-is…

…sues (#263) * SED-3086 Automation package and Assertion Plan execution stability issues * SED-3086 fixing junit * SED-3086 applying minor PR feedback
exense · May 13, 2024 · a045d7c · a045d7c
1 parent f0697f3
commit a045d7c
Show file tree

Hide file tree

Showing 12 changed files with 117 additions and 21 deletions.
diff --git a/...s-controller/src/main/java/step/automation/packages/AutomationPackageExecutionPlugin.java b/...s-controller/src/main/java/step/automation/packages/AutomationPackageExecutionPlugin.java
@@ -2,13 +2,15 @@
 
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import step.core.accessors.AbstractOrganizableObject;
 import step.core.execution.ExecutionContext;
 import step.core.plans.Plan;
 import step.core.plugins.IgnoreDuringAutoDiscovery;
 import step.core.plugins.Plugin;
 import step.core.plugins.exceptions.PluginCriticalException;
 import step.engine.plugins.AbstractExecutionEnginePlugin;
 
+import static step.automation.packages.AutomationPackageLocks.BYPASS_AUTOMATION_PACKAGE_LOCK;
 import static step.automation.packages.AutomationPackagePlugin.AUTOMATION_PACKAGE_READ_LOCK_TIMEOUT_SECS;
 import static step.automation.packages.AutomationPackagePlugin.AUTOMATION_PACKAGE_READ_LOCK_TIMEOUT_SECS_DEFAULT;
 
@@ -30,40 +32,66 @@ public AutomationPackageExecutionPlugin(AutomationPackageLocks automationPackage
     @Override
     public void executionStart(ExecutionContext context) {
         super.executionStart(context);
-        String automationPackageId = getAutomationPackageId(context);
-        if (automationPackageId != null) {
+        if (shouldLock(context)) {
+            String automationPackageId = getAutomationPackageId(context);
             try {
+                debugLog(context, "Trying to acquire read lock on automation package.");
                 boolean locked = automationPackageLocks.tryReadLock(automationPackageId);
                 if (!locked) {
-                    logger.debug("Timeout while acquiring read lock on automation package " + automationPackageId);
+                    debugLog(context, "Timeout while acquiring read lock on automation package.");
                     throw new PluginCriticalException("Timeout while acquiring lock on automation package with id " +
                             automationPackageId + ". This usually means that an update of this automation package is on-going and took more than the property " +
                             AUTOMATION_PACKAGE_READ_LOCK_TIMEOUT_SECS + " (default " + AUTOMATION_PACKAGE_READ_LOCK_TIMEOUT_SECS_DEFAULT + " seconds)");
                 }
-                logger.debug("Acquired read lock on automation package " + automationPackageId);
+                debugLog(context,"Acquired read lock on automation package.");
             } catch (InterruptedException e) {
                 throw new PluginCriticalException("Thread interrupted while acquiring lock on automation package with id " + automationPackageId);
             }
         }
     }
 
+    private void debugLog(ExecutionContext context, String message) {
+        if (logger.isDebugEnabled()) {
+            Plan plan = context.getPlan();
+            String planName = (plan != null) ? plan.getAttribute(AbstractOrganizableObject.NAME) : "unresolved";
+            String automationPackageId = getAutomationPackageId(context);
+            logger.debug(message + " Id: " + automationPackageId + ", execution id: " +
+                    context.getExecutionId() + ",  plan: " + planName);
+        }
+    }
+
+    public boolean shouldLock(ExecutionContext context) {
+        if (getAutomationPackageId(context) == null) {
+            return false;
+        } else {
+            Object byPass = context.getExecutionParameters().getCustomField(BYPASS_AUTOMATION_PACKAGE_LOCK);
+            if (byPass == null) {
+                return true;
+            } else if (byPass instanceof Boolean) {
+                return !(Boolean) byPass;
+            } else {
+                throw new RuntimeException(BYPASS_AUTOMATION_PACKAGE_LOCK + " is set in context but its value is not a boolean: " + byPass);
+            }
+        }
+    }
+
     private static String getAutomationPackageId(ExecutionContext context) {
         Plan plan = context.getPlan();
         return (plan != null) ? (String) plan.getCustomField(AutomationPackageEntity.AUTOMATION_PACKAGE_ID):
                 null;
     }
 
     @Override
-    public void afterExecutionEnd(ExecutionContext context) {
-        super.afterExecutionEnd(context);
-        String automationPackageId = getAutomationPackageId(context);
-        if (automationPackageId != null) {
+    public void executionFinally(ExecutionContext context) {
+        super.executionFinally(context);
+        if (shouldLock(context)) {
+            String automationPackageId = getAutomationPackageId(context);
             try {
                 automationPackageLocks.readUnlock(automationPackageId);
-                logger.debug("Released read lock on automation package " + automationPackageId);
+                debugLog(context, "Released read lock on automation package.");
             } catch (java.lang.IllegalMonitorStateException e) {
                 //occurs whenever the lock was not acquired in execution start due to timeout
-                logger.debug("No read lock to be released for automation package " + automationPackageId);
+                debugLog(context, "No read lock to be released for automation package.");
             }
         }
     }

diff --git a/...n-packages-controller/src/main/java/step/automation/packages/AutomationPackagePlugin.java b/...n-packages-controller/src/main/java/step/automation/packages/AutomationPackagePlugin.java
@@ -46,7 +46,7 @@ public class AutomationPackagePlugin extends AbstractControllerPlugin {
 
     private static final Logger log = LoggerFactory.getLogger(AutomationPackagePlugin.class);
     public static final String AUTOMATION_PACKAGE_READ_LOCK_TIMEOUT_SECS = "automationPackage.lock.read.timeout.secs";
-    public static final int AUTOMATION_PACKAGE_READ_LOCK_TIMEOUT_SECS_DEFAULT = 120;
+    public static final int AUTOMATION_PACKAGE_READ_LOCK_TIMEOUT_SECS_DEFAULT = 600;
     protected AutomationPackageLocks automationPackageLocks;
 
     @Override

diff --git a/...ation-packages-manager/src/main/java/step/automation/packages/AutomationPackageLocks.java b/...ation-packages-manager/src/main/java/step/automation/packages/AutomationPackageLocks.java
@@ -8,6 +8,8 @@
 
 public class AutomationPackageLocks {
 
+    public static final String BYPASS_AUTOMATION_PACKAGE_LOCK = "BYPASS_AUTOMATION_PACKAGE_LOCK";
+
     private final Map<String, ReadWriteLock> locksMap = new ConcurrentHashMap<>();
     private final int readLockTimeoutSeconds;
 

diff --git a/...ntroller/step-controller-server/src/main/java/step/core/scheduler/ExecutionScheduler.java b/...ntroller/step-controller-server/src/main/java/step/core/scheduler/ExecutionScheduler.java
@@ -147,6 +147,10 @@ public String execute(ExecutionParameters executionParameters) {
 		return executor.execute(executionParameters);
 	}
 
+	public String executeNested(ExecutionParameters executionParameters) {
+		return executor.executeNested(executionParameters);
+	}
+
 	public String executeExecutionTask(String executionTaskID, String user) {
 		ExecutiontTaskParameters task = get(executionTaskID);
 		task.getExecutionsParameters().setUserID(user);

diff --git a/step-controller/step-controller-server/src/main/java/step/core/scheduler/Executor.java b/step-controller/step-controller-server/src/main/java/step/core/scheduler/Executor.java
@@ -46,7 +46,8 @@ public class Executor {
 	private final Logger logger = LoggerFactory.getLogger(Executor.class);
 
 	private Scheduler scheduler;
-	private SchedulerFactory schedulerFactory;
+
+	private Scheduler nestedScheduler;
 	private ExecutionEngine executionEngine;
 	private Configuration configuration;
 
@@ -64,9 +65,15 @@ public Executor(GlobalContext globalContext) {
 
 		try {
 			Properties props = getProperties();
-			schedulerFactory = new StdSchedulerFactory(props);
+			StdSchedulerFactory schedulerFactory = new StdSchedulerFactory(props);
 			scheduler = schedulerFactory.getScheduler();
 			scheduler.setJobFactory(new ExecutionJobFactory(globalContext, executionEngine));
+			//Create another scheduler with same number of threads for nested executions to avoid deadlock
+			Properties propsNested = getProperties();
+			propsNested.put("org.quartz.scheduler.instanceName","NestedExecutionsScheduler");
+			StdSchedulerFactory nestedSchedulerFactory = new StdSchedulerFactory(propsNested);
+			nestedScheduler = nestedSchedulerFactory.getScheduler();
+			nestedScheduler.setJobFactory(new ExecutionJobFactory(globalContext, executionEngine));
 		} catch (SchedulerException e) {
 			throw new RuntimeException(e);
 		}
@@ -75,8 +82,9 @@ public Executor(GlobalContext globalContext) {
 	protected Executor() {
 	}
 
-	protected Executor(Scheduler scheduler) {
+	protected Executor(Scheduler scheduler, Scheduler nestedScheduler) {
 		this.scheduler = scheduler;
+		this.nestedScheduler = nestedScheduler;
 	}
 
 	private Properties getProperties() {
@@ -87,7 +95,12 @@ private Properties getProperties() {
 
 	public void shutdown() {
 		try {
-			scheduler.shutdown(true);
+			if (scheduler != null) {
+				scheduler.shutdown(true);
+			}
+			if (nestedScheduler != null) {
+				nestedScheduler.shutdown(true);
+			}
 		} catch (SchedulerException e) {
 			throw new RuntimeException(e);
 		}
@@ -96,6 +109,7 @@ public void shutdown() {
 	public void start() {
 		try {
 			scheduler.start();
+			nestedScheduler.start();
 		} catch (SchedulerException e) {
 			throw new RuntimeException(e);
 		}
@@ -184,6 +198,18 @@ public String execute(ExecutionParameters executionParameters) {
 		scheduleExistingExecutionNow(executionID);
 		return executionID;
 	}
+
+	public String executeNested(ExecutionParameters executionParameters) {
+		String executionID = executionEngine.initializeExecution(executionParameters);
+		Trigger trigger = TriggerBuilder.newTrigger().startNow().build();
+		JobDetail job = buildSingleJob(executionID);
+		try {
+			nestedScheduler.scheduleJob(job, trigger);
+		} catch (SchedulerException e) {
+			throw new RuntimeException("An unexpected error occurred while scheduling job "+ job.toString(), e);
+		}
+		return executionID;
+	}
 
 	public String execute(ExecutiontTaskParameters executionTaskParameters) {
 		String executionID = executionEngine.initializeExecution(executionTaskParameters);

diff --git a/.../step-controller-server/src/test/java/step/core/scheduler/ExecutionSchedulerCronTest.java b/.../step-controller-server/src/test/java/step/core/scheduler/ExecutionSchedulerCronTest.java
@@ -32,7 +32,7 @@ public TestExecutor getExecutor() {
 
 	public static class TestExecutor extends Executor {
 		public TestExecutor(Scheduler scheduler) {
-			super(scheduler);
+			super(scheduler, scheduler);
 
 		}
 	}

diff --git a/...s/step-functions-package/src/main/java/step/functions/packages/FunctionPackagePlugin.java b/...s/step-functions-package/src/main/java/step/functions/packages/FunctionPackagePlugin.java
@@ -91,7 +91,9 @@ protected void createScreenInputsIfNecessary(GlobalContext context) {
 	@Override
 	public void serverStop(GlobalContext context) {
 		try {
-			packageManager.close();
+			if (packageManager != null) {
+				packageManager.close();
+			}
 		} catch (IOException e) {
 			logger.error("Error while closing package manager", e);
 		}

diff --git a/step-plans/step-plans-core/src/main/java/step/core/execution/ExecutionEngineRunner.java b/step-plans/step-plans-core/src/main/java/step/core/execution/ExecutionEngineRunner.java
@@ -37,6 +37,7 @@
 import step.core.execution.model.ExecutionParameters;
 import step.core.execution.model.ExecutionStatus;
 import step.core.execution.model.ReportExport;
+import step.core.miscellaneous.ReportNodeAttachmentManager;
 import step.core.plans.Plan;
 import step.core.plans.PlanAccessor;
 import step.core.plans.runner.PlanRunnerResult;
@@ -143,10 +144,26 @@ protected PlanRunnerResult execute() {
 		} catch (Throwable e) {
 			logger.error("An error occurred while running test. Execution ID: " + executionId, e);
 			executionLifecycleManager.updateExecutionResult(executionContext, ReportNodeStatus.TECHNICAL_ERROR);
+			ReportNode report = executionContext.getReport();
+			ReportNodeAttachmentManager attachmentManager = new ReportNodeAttachmentManager(executionContext);
+            try {
+                report.addAttachment(attachmentManager.createAttachment(e));
+            } catch (ReportNodeAttachmentManager.AttachmentQuotaException ex) {
+                logger.info("Exception could not be attached to root report node due to attachments quota.");
+            }
+			report.addError(e.getMessage());
+			persistReportNode(report);
+
 		} finally {
 			updateStatus(ExecutionStatus.ENDED);
-			executionLifecycleManager.executionEnded();
-			postExecution(executionContext);
+			try {
+				executionLifecycleManager.executionEnded();
+			} finally {
+				//Make sure that even plugin critical exception occurs the mandatory hooks and postExecutions are performed
+				executionLifecycleManager.executionFinally();
+				postExecution(executionContext);
+			}
+
 		}
 		return result;
 	}

diff --git a/step-plans/step-plans-core/src/main/java/step/core/execution/type/ExecutionTypePlugin.java b/step-plans/step-plans-core/src/main/java/step/core/execution/type/ExecutionTypePlugin.java
@@ -18,7 +18,9 @@ public void initializeExecutionEngineContext(AbstractExecutionEngineContext pare
     }
 
     @Override
-    public void executionStart(ExecutionContext context) {
-        context.put(ExecutionTypeManager.class, executionTypeManager);
+    public void initializeExecutionContext(ExecutionEngineContext executionEngineContext, ExecutionContext executionContext) {
+        super.initializeExecutionContext(executionEngineContext, executionContext);
+        executionContext.put(ExecutionTypeManager.class, executionTypeManager);
     }
+
 }
diff --git a/step-plans/step-plans-core/src/main/java/step/core/plugins/ExecutionCallbacks.java b/step-plans/step-plans-core/src/main/java/step/core/plugins/ExecutionCallbacks.java
@@ -77,4 +77,10 @@ public interface ExecutionCallbacks {
 	public void forceStopExecution(ExecutionContext context);
 
 	public void afterExecutionEnd(ExecutionContext context);
+
+	/* This method is called after afterExecutionEnd. It is meant to be used for code that should
+	   always be executed, i.e. even if some PluginCriticalException occurred. This method should never throw
+	   a PluginCriticalException to make sure all plugins executionFinally are invoked
+	 */
+	public void executionFinally(ExecutionContext context);
 }
diff --git a/...-plans/step-plans-core/src/main/java/step/engine/execution/ExecutionLifecycleManager.java b/...-plans/step-plans-core/src/main/java/step/engine/execution/ExecutionLifecycleManager.java
@@ -72,6 +72,10 @@ public void executionStarted() {
 	public void executionEnded() {
 		executionCallbacks.afterExecutionEnd(context);
 	}
+
+	public void executionFinally() {
+		executionCallbacks.executionFinally(context);
+	}
 
 	public void updateStatus(ExecutionStatus newStatus) {
 		executionManager.updateStatus(context,newStatus);

diff --git a/...lans/step-plans-core/src/main/java/step/engine/plugins/AbstractExecutionEnginePlugin.java b/...lans/step-plans-core/src/main/java/step/engine/plugins/AbstractExecutionEnginePlugin.java
@@ -102,4 +102,9 @@ public void afterFunctionExecution(ExecutionContext context, ReportNode node, Fu
 
 	@Override
 	public void forceStopExecution(ExecutionContext context) {}
+
+	@Override
+	public void executionFinally(ExecutionContext context) {
+
+	}
 }