From d08949e7a9b1655239d23003e38860ee81161ea7 Mon Sep 17 00:00:00 2001 From: Sam Van Oort Date: Tue, 2 Oct 2018 22:09:42 -0400 Subject: [PATCH 1/7] First hack at correcting the completion of the AsynchronousExecution --- .../plugins/workflow/job/WorkflowRun.java | 30 +++++++++---------- 1 file changed, 14 insertions(+), 16 deletions(-) diff --git a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java index 591274d2..d2b2d266 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java @@ -580,6 +580,16 @@ private void finish(@Nonnull Result r, @CheckForNull Throwable t) { setResult(r); completed = Boolean.TRUE; duration = Math.max(0, System.currentTimeMillis() - getStartTimeInMillis()); + + } + Executor executor = getExecutor(); + if (executor != null) { + AsynchronousExecution asynchronousExecution = executor.getAsynchronousExecution(); + if (asynchronousExecution != null) { + asynchronousExecution.completed(null); + } + } else { + LOGGER.log(Level.SEVERE, "Build tried to complete when in fact already done."); } try { LOGGER.log(Level.INFO, "{0} completed: {1}", new Object[]{toString(), getResult()}); @@ -1122,22 +1132,10 @@ public void save() throws IOException { } boolean completeAsynchronousExecution = false; - try { - synchronized (this) { - completeAsynchronousExecution = Boolean.TRUE.equals(completed); - PipelineIOUtils.writeByXStream(this, loc, XSTREAM2, isAtomic); - SaveableListener.fireOnChange(this, file); - } - } finally { - if (completeAsynchronousExecution) { - Executor executor = getExecutor(); - if (executor != null) { - AsynchronousExecution asynchronousExecution = executor.getAsynchronousExecution(); - if (asynchronousExecution != null) { - asynchronousExecution.completed(null); - } - } - } + synchronized (this) { + completeAsynchronousExecution = Boolean.TRUE.equals(completed); + PipelineIOUtils.writeByXStream(this, loc, XSTREAM2, isAtomic); + SaveableListener.fireOnChange(this, file); } } } From 877dafd14083af0f3c7d0d0bc91e4170dc14b209 Mon Sep 17 00:00:00 2001 From: Sam Van Oort Date: Wed, 3 Oct 2018 17:48:29 -0400 Subject: [PATCH 2/7] Findbugs fix --- .../java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java index d2b2d266..e9362fa4 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java @@ -1131,9 +1131,7 @@ public void save() throws IOException { isAtomic = hint.isAtomicWrite(); } - boolean completeAsynchronousExecution = false; synchronized (this) { - completeAsynchronousExecution = Boolean.TRUE.equals(completed); PipelineIOUtils.writeByXStream(this, loc, XSTREAM2, isAtomic); SaveableListener.fireOnChange(this, file); } From c6bd9b0b071358028138e06a9353568f2974700e Mon Sep 17 00:00:00 2001 From: Sam Van Oort Date: Thu, 4 Oct 2018 14:00:05 -0400 Subject: [PATCH 3/7] Fixes to completion logic --- .../plugins/workflow/job/WorkflowRun.java | 42 ++++++++++++------- 1 file changed, 26 insertions(+), 16 deletions(-) diff --git a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java index e9362fa4..26066601 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java @@ -181,7 +181,7 @@ public String url() { * Flag for whether or not the build has completed somehow. * This was previously a transient field, so we may need to recompute in {@link #onLoad} based on {@link FlowExecution#isComplete}. */ - Boolean completed; // Non-private for testing + volatile Boolean completed; // Non-private for testing /** Protects the access to logsToCopy, completed, and branchNameCache that are used in the logCopy process */ private transient Object logCopyGuard = new Object(); @@ -508,7 +508,7 @@ private String key() { new XmlFile(XSTREAM,new File(getRootDir(),"build.xml")).unmarshal(this); } - @Override protected void onLoad() { + @Override protected void onLoad() { // Here there be DRAGONS: due to lazy-loading and subtle threading risks, be very cautious! try { synchronized (getLogCopyGuard()) { if (executionLoaded) { @@ -543,8 +543,10 @@ private String key() { } } else { // Execution nulled due to a critical failure, explicitly mark completed completed = Boolean.TRUE; + needsToPersist = true; // Make sure we save toggled state } - } else if (execution == null) { + } else if (execution == null && completed != Boolean.TRUE) { + needsToPersist = true; // Make sure we save toggled state completed = Boolean.TRUE; } if (needsToPersist && completed) { @@ -572,6 +574,20 @@ private String key() { } } + private void endExecutionTask() { + try { + Executor executor = getExecutor(); + if (executor != null) { + AsynchronousExecution asynchronousExecution = executor.getAsynchronousExecution(); + if (asynchronousExecution != null) { + asynchronousExecution.completed(null); + } + } + } catch (Exception ex) { + LOGGER.log(Level.WARNING, "Error when trying to end the FlyWeightTask for run "+this, ex); + } + } + /** Handles normal build completion (including errors) but also handles the case that the flow did not even start correctly, for example due to an error in {@link FlowExecution#start}. */ private void finish(@Nonnull Result r, @CheckForNull Throwable t) { boolean nullListener = false; @@ -582,15 +598,6 @@ private void finish(@Nonnull Result r, @CheckForNull Throwable t) { duration = Math.max(0, System.currentTimeMillis() - getStartTimeInMillis()); } - Executor executor = getExecutor(); - if (executor != null) { - AsynchronousExecution asynchronousExecution = executor.getAsynchronousExecution(); - if (asynchronousExecution != null) { - asynchronousExecution.completed(null); - } - } else { - LOGGER.log(Level.SEVERE, "Build tried to complete when in fact already done."); - } try { LOGGER.log(Level.INFO, "{0} completed: {1}", new Object[]{toString(), getResult()}); if (nullListener) { @@ -615,7 +622,8 @@ private void finish(@Nonnull Result r, @CheckForNull Throwable t) { } listener = null; } - saveWithoutFailing(); // TODO useless if we are inside a BulkChange + saveWithoutFailing(); + endExecutionTask(); Timer.get().submit(() -> { try { getParent().logRotate(); @@ -624,7 +632,8 @@ private void finish(@Nonnull Result r, @CheckForNull Throwable t) { } }); onEndBuilding(); - } finally { // Ensure this is ALWAYS removed from FlowExecutionList + } finally { // Ensure this is ALWAYS removed from FlowExecutionList and finished + endExecutionTask(); // Just in case an exception was thrown above FlowExecutionList.get().unregister(new Owner(this)); } @@ -1119,8 +1128,9 @@ private void saveWithoutFailing() { @Override public void save() throws IOException { - - if(BulkChange.contains(this)) return; + /* Checking for completion ensures the final save can complete. + */ + if(BulkChange.contains(this) && completed != Boolean.TRUE) return; File loc = new File(getRootDir(),"build.xml"); XmlFile file = new XmlFile(XSTREAM,loc); From e8079972b108de38df5eaab6c49805ae74077e68 Mon Sep 17 00:00:00 2001 From: Sam Van Oort Date: Thu, 4 Oct 2018 15:08:04 -0400 Subject: [PATCH 4/7] Remove some pieces that are not strictly required to see if they triggered CI-only failures --- .../java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java | 4 +--- .../plugins/workflow/job/WorkflowRunRestartTest.java | 1 - 2 files changed, 1 insertion(+), 4 deletions(-) diff --git a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java index 26066601..f35310de 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java @@ -543,10 +543,8 @@ private String key() { } } else { // Execution nulled due to a critical failure, explicitly mark completed completed = Boolean.TRUE; - needsToPersist = true; // Make sure we save toggled state } - } else if (execution == null && completed != Boolean.TRUE) { - needsToPersist = true; // Make sure we save toggled state + } else if (execution == null) { completed = Boolean.TRUE; } if (needsToPersist && completed) { diff --git a/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java b/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java index a8a3ea72..0f552fec 100644 --- a/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java +++ b/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java @@ -129,7 +129,6 @@ public class WorkflowRunRestartTest { WorkflowJob p = r.jenkins.getItemByFullName("p", WorkflowJob.class); WorkflowRun b = p.getBuildByNumber(1); assertNotNull(b.asFlowExecutionOwner()); - assertNull(b.execution.getOwner()); assertFalse(b.executionLoaded); assertTrue(b.completed); assertFalse(b.isBuilding()); From bfc87ffe408264e3ac1f7d01c5aacabdc13cf695 Mon Sep 17 00:00:00 2001 From: Sam Van Oort Date: Thu, 4 Oct 2018 15:42:46 -0400 Subject: [PATCH 5/7] One final attempt to debug why lazy loading is not lazy --- .../org/jenkinsci/plugins/workflow/job/WorkflowRun.java | 6 ++++++ .../plugins/workflow/job/WorkflowRunRestartTest.java | 3 +++ 2 files changed, 9 insertions(+) diff --git a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java index f35310de..06a5255d 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java @@ -651,12 +651,18 @@ private void finish(@Nonnull Result r, @CheckForNull Throwable t) { StashManager.clearAll(this); } + public static boolean LOG_GET_EXECUTION = false; + /** * Gets the associated execution state, and do a more expensive loading operation if not initialized. * Performs all the needed initialization for the execution pre-loading too -- sets the executionPromise, adds Listener, calls onLoad on it etc. * @return non-null after the flow has started, even after finished (but may be null temporarily when about to start, or if starting failed) */ public @CheckForNull FlowExecution getExecution() { + if (LOG_GET_EXECUTION) { + LOGGER.log(Level.SEVERE, "Logging when getExecution was invoked", new Exception("Ran getExecution")); + } + if (executionLoaded || execution == null) { // Avoids highly-contended synchronization on run return execution; } else { // Try to lazy-load execution diff --git a/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java b/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java index 0f552fec..4820d5c6 100644 --- a/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java +++ b/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java @@ -125,10 +125,13 @@ public class WorkflowRunRestartTest { assertTrue(run.executionLoaded); assertNotNull(run.getExecution().getOwner()); }); + WorkflowRun.LOG_GET_EXECUTION = true; story.then(r -> { + WorkflowRun.LOG_GET_EXECUTION = true; WorkflowJob p = r.jenkins.getItemByFullName("p", WorkflowJob.class); WorkflowRun b = p.getBuildByNumber(1); assertNotNull(b.asFlowExecutionOwner()); + assertNull(b.execution.getOwner()); assertFalse(b.executionLoaded); assertTrue(b.completed); assertFalse(b.isBuilding()); From 330a2af980022cff09fed7713f1a072269209fb9 Mon Sep 17 00:00:00 2001 From: Sam Van Oort Date: Thu, 4 Oct 2018 15:48:45 -0400 Subject: [PATCH 6/7] hardening testcases against timing quirks --- .../plugins/workflow/job/CpsPersistenceTest.java | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/src/test/java/org/jenkinsci/plugins/workflow/job/CpsPersistenceTest.java b/src/test/java/org/jenkinsci/plugins/workflow/job/CpsPersistenceTest.java index e963f7ec..13ce2edf 100644 --- a/src/test/java/org/jenkinsci/plugins/workflow/job/CpsPersistenceTest.java +++ b/src/test/java/org/jenkinsci/plugins/workflow/job/CpsPersistenceTest.java @@ -79,9 +79,8 @@ private static Stack getCpsBlockStartNodes(CpsFlowExecution exec /** Verifies all the assumptions about a cleanly finished build. */ static void assertCompletedCleanly(WorkflowRun run) throws Exception { - if (run.isBuilding()) { - System.out.println("Run initially building, going to wait a second to see if it finishes, run="+run); - Thread.sleep(1000); + while (run.isBuilding()) { + Thread.sleep(100); // Somewhat variable speeds } Assert.assertFalse(run.isBuilding()); Assert.assertNotNull(run.getResult()); @@ -103,7 +102,9 @@ static void assertCompletedCleanly(WorkflowRun run) throws Exception { Stack starts = getCpsBlockStartNodes(cpsExec); Assert.assertTrue(starts == null || starts.isEmpty()); Thread.sleep(1000); // TODO seems to be flaky - Assert.assertFalse(cpsExec.blocksRestart()); + while (cpsExec.blocksRestart()) { + Thread.sleep(100); + } } else { System.out.println("WARNING: no FlowExecutionForBuild"); } From d24752dbb6be38c48a5d2fd9a3770edccaed8c8a Mon Sep 17 00:00:00 2001 From: Sam Van Oort Date: Thu, 4 Oct 2018 15:53:58 -0400 Subject: [PATCH 7/7] Revert "One final attempt to debug why lazy loading is not lazy" This reverts commit bfc87ffe408264e3ac1f7d01c5aacabdc13cf695. --- .../org/jenkinsci/plugins/workflow/job/WorkflowRun.java | 6 ------ .../plugins/workflow/job/WorkflowRunRestartTest.java | 3 --- 2 files changed, 9 deletions(-) diff --git a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java index 06a5255d..f35310de 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java @@ -651,18 +651,12 @@ private void finish(@Nonnull Result r, @CheckForNull Throwable t) { StashManager.clearAll(this); } - public static boolean LOG_GET_EXECUTION = false; - /** * Gets the associated execution state, and do a more expensive loading operation if not initialized. * Performs all the needed initialization for the execution pre-loading too -- sets the executionPromise, adds Listener, calls onLoad on it etc. * @return non-null after the flow has started, even after finished (but may be null temporarily when about to start, or if starting failed) */ public @CheckForNull FlowExecution getExecution() { - if (LOG_GET_EXECUTION) { - LOGGER.log(Level.SEVERE, "Logging when getExecution was invoked", new Exception("Ran getExecution")); - } - if (executionLoaded || execution == null) { // Avoids highly-contended synchronization on run return execution; } else { // Try to lazy-load execution diff --git a/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java b/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java index 4820d5c6..0f552fec 100644 --- a/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java +++ b/src/test/java/org/jenkinsci/plugins/workflow/job/WorkflowRunRestartTest.java @@ -125,13 +125,10 @@ public class WorkflowRunRestartTest { assertTrue(run.executionLoaded); assertNotNull(run.getExecution().getOwner()); }); - WorkflowRun.LOG_GET_EXECUTION = true; story.then(r -> { - WorkflowRun.LOG_GET_EXECUTION = true; WorkflowJob p = r.jenkins.getItemByFullName("p", WorkflowJob.class); WorkflowRun b = p.getBuildByNumber(1); assertNotNull(b.asFlowExecutionOwner()); - assertNull(b.execution.getOwner()); assertFalse(b.executionLoaded); assertTrue(b.completed); assertFalse(b.isBuilding());