From a045d7c411db7bff7ca70df1112c8c126369f71f Mon Sep 17 00:00:00 2001 From: David Stephan Date: Mon, 13 May 2024 14:05:54 +0200 Subject: [PATCH] SED-3086 automation-package-and-assertion-plan-execution-stability-issues (#263) * SED-3086 Automation package and Assertion Plan execution stability issues * SED-3086 fixing junit * SED-3086 applying minor PR feedback --- .../AutomationPackageExecutionPlugin.java | 48 +++++++++++++++---- .../packages/AutomationPackagePlugin.java | 2 +- .../packages/AutomationPackageLocks.java | 2 + .../core/scheduler/ExecutionScheduler.java | 4 ++ .../java/step/core/scheduler/Executor.java | 34 +++++++++++-- .../scheduler/ExecutionSchedulerCronTest.java | 2 +- .../packages/FunctionPackagePlugin.java | 4 +- .../core/execution/ExecutionEngineRunner.java | 21 +++++++- .../execution/type/ExecutionTypePlugin.java | 6 ++- .../step/core/plugins/ExecutionCallbacks.java | 6 +++ .../execution/ExecutionLifecycleManager.java | 4 ++ .../AbstractExecutionEnginePlugin.java | 5 ++ 12 files changed, 117 insertions(+), 21 deletions(-) diff --git a/step-automation-packages/step-automation-packages-controller/src/main/java/step/automation/packages/AutomationPackageExecutionPlugin.java b/step-automation-packages/step-automation-packages-controller/src/main/java/step/automation/packages/AutomationPackageExecutionPlugin.java index cf64a7cce..b100d985d 100644 --- a/step-automation-packages/step-automation-packages-controller/src/main/java/step/automation/packages/AutomationPackageExecutionPlugin.java +++ b/step-automation-packages/step-automation-packages-controller/src/main/java/step/automation/packages/AutomationPackageExecutionPlugin.java @@ -2,6 +2,7 @@ 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; @@ -9,6 +10,7 @@ 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,23 +32,49 @@ 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): @@ -54,16 +82,16 @@ private static String getAutomationPackageId(ExecutionContext context) { } @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/step-automation-packages/step-automation-packages-controller/src/main/java/step/automation/packages/AutomationPackagePlugin.java b/step-automation-packages/step-automation-packages-controller/src/main/java/step/automation/packages/AutomationPackagePlugin.java index 4471bbbb1..b03ee5c39 100644 --- a/step-automation-packages/step-automation-packages-controller/src/main/java/step/automation/packages/AutomationPackagePlugin.java +++ b/step-automation-packages/step-automation-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/step-automation-packages/step-automation-packages-manager/src/main/java/step/automation/packages/AutomationPackageLocks.java b/step-automation-packages/step-automation-packages-manager/src/main/java/step/automation/packages/AutomationPackageLocks.java index c7ce64b6e..d489001b7 100644 --- a/step-automation-packages/step-automation-packages-manager/src/main/java/step/automation/packages/AutomationPackageLocks.java +++ b/step-automation-packages/step-automation-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 locksMap = new ConcurrentHashMap<>(); private final int readLockTimeoutSeconds; diff --git a/step-controller/step-controller-server/src/main/java/step/core/scheduler/ExecutionScheduler.java b/step-controller/step-controller-server/src/main/java/step/core/scheduler/ExecutionScheduler.java index 3cc5f9263..9939f3f85 100644 --- a/step-controller/step-controller-server/src/main/java/step/core/scheduler/ExecutionScheduler.java +++ b/step-controller/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 index d8306e632..2daec5d18 100644 --- 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/step-controller-server/src/test/java/step/core/scheduler/ExecutionSchedulerCronTest.java b/step-controller/step-controller-server/src/test/java/step/core/scheduler/ExecutionSchedulerCronTest.java index 042141184..deb8d069a 100644 --- a/step-controller/step-controller-server/src/test/java/step/core/scheduler/ExecutionSchedulerCronTest.java +++ b/step-controller/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/step-functions/step-functions-package/src/main/java/step/functions/packages/FunctionPackagePlugin.java b/step-functions/step-functions-package/src/main/java/step/functions/packages/FunctionPackagePlugin.java index d9b289870..eb3df6711 100644 --- a/step-functions/step-functions-package/src/main/java/step/functions/packages/FunctionPackagePlugin.java +++ b/step-functions/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 index 417fbefc1..dc8303dad 100644 --- 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 index 74c8e33ba..19b011009 100644 --- 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 index d83a1e1f7..ccb2508a4 100644 --- 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/step-plans/step-plans-core/src/main/java/step/engine/execution/ExecutionLifecycleManager.java b/step-plans/step-plans-core/src/main/java/step/engine/execution/ExecutionLifecycleManager.java index cd44ba93a..012850ad6 100644 --- a/step-plans/step-plans-core/src/main/java/step/engine/execution/ExecutionLifecycleManager.java +++ b/step-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/step-plans/step-plans-core/src/main/java/step/engine/plugins/AbstractExecutionEnginePlugin.java b/step-plans/step-plans-core/src/main/java/step/engine/plugins/AbstractExecutionEnginePlugin.java index c04490de3..d495ee2a8 100644 --- a/step-plans/step-plans-core/src/main/java/step/engine/plugins/AbstractExecutionEnginePlugin.java +++ b/step-plans/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) { + + } }