From dd4256af209ba0218a410ffb5870ddea8391d770 Mon Sep 17 00:00:00 2001 From: christ66 Date: Mon, 12 Oct 2015 01:09:52 -0700 Subject: [PATCH 01/76] Add more logging to Queue.maintain in order to understand why potential builds could be blocked queue and never executed. --- core/src/main/java/hudson/model/Queue.java | 31 +++++++++++++++++++--- 1 file changed, 27 insertions(+), 4 deletions(-) diff --git a/core/src/main/java/hudson/model/Queue.java b/core/src/main/java/hudson/model/Queue.java index c265e477df..cba47d30a2 100644 --- a/core/src/main/java/hudson/model/Queue.java +++ b/core/src/main/java/hudson/model/Queue.java @@ -1385,9 +1385,13 @@ public class Queue extends ResourceController implements Saveable { // we need to clear lost pendings as we cannot know what work unit was on this executor // while it is interrupted. (All this dancing is a result of Executor extending Thread) lostPendings.clear(); // we'll get them next time around when the flag is cleared. + LOGGER.log(Level.FINEST, + "Interrupt thread for executor {0} is set and we do not know what work unit was on the executor.", + e.getDisplayName()); continue; } if (e.isParking()) { + LOGGER.log(Level.FINEST, "{0} is parking and is waiting for a job to execute.", e.getDisplayName()); parked.put(e, new JobOffer(e)); } final WorkUnit workUnit = e.getCurrentWorkUnit(); @@ -1419,7 +1423,12 @@ public class Queue extends ResourceController implements Saveable { Collections.sort(blockedItems, QueueSorter.DEFAULT_BLOCKED_ITEM_COMPARATOR); } for (BlockedItem p : blockedItems) { + LOGGER.log(Level.FINER, "Current blocked item: {0}", p.task.getFullDisplayName()); if (!isBuildBlocked(p) && allowNewBuildableTask(p.task)) { + LOGGER.log(Level.INFO, + "BlockedItem {0}: blocked -> buildable as the build is not blocked and new tasks are allowed", + p.task.getFullDisplayName()); + // ready to be executed Runnable r = makeBuildable(new BuildableItem(p)); if (r != null) { @@ -1438,8 +1447,10 @@ public class Queue extends ResourceController implements Saveable { while (!waitingList.isEmpty()) { WaitingItem top = peek(); - if (top.timestamp.compareTo(new GregorianCalendar()) > 0) + if (top.timestamp.compareTo(new GregorianCalendar()) > 0) { + LOGGER.log(Level.FINE, "Finished moving all ready items from queue."); break; // finished moving all ready items from queue + } top.leave(this); Task p = top.task; @@ -1447,8 +1458,10 @@ public class Queue extends ResourceController implements Saveable { // ready to be executed immediately Runnable r = makeBuildable(new BuildableItem(top)); if (r != null) { + LOGGER.log(Level.FINE, "Executing runnable {0}", top.task.getFullDisplayName()); r.run(); } else { + LOGGER.log(Level.FINEST, "Item {0} was unable to be made a buildable and is now a blocked item.", top.task.getFullDisplayName()); new BlockedItem(top).enter(this); } } else { @@ -1482,15 +1495,19 @@ public class Queue extends ResourceController implements Saveable { Runnable r = makeFlyWeightTaskBuildable(new BuildableItem(p)); if (r != null) { p.leave(this); + LOGGER.log(Level.FINEST, "Executing flyweight task {0}", p.task.getFullDisplayName()); r.run(); updateSnapshot(); } } else { List candidates = new ArrayList(parked.size()); - for (JobOffer j : parked.values()) - if (j.canTake(p)) + for (JobOffer j : parked.values()) { + if (j.canTake(p)) { + LOGGER.log(Level.FINEST, "Potential candidate for "); candidates.add(j); + } + } MappingWorksheet ws = new MappingWorksheet(p, candidates); Mapping m = loadBalancer.map(p.task, ws); @@ -1505,10 +1522,12 @@ public class Queue extends ResourceController implements Saveable { // found a matching executor. use it. WorkUnitContext wuc = new WorkUnitContext(p); + LOGGER.log(Level.FINER, "Found a matching executor for {0}. Using it.", p.task.getFullDisplayName()); m.execute(wuc); p.leave(this); if (!wuc.getWorkUnits().isEmpty()) { + LOGGER.log(Level.FINE, "BuildableItem {0} marked as pending.", p.task.getFullDisplayName()); makePending(p); } else @@ -1542,7 +1561,7 @@ public class Queue extends ResourceController implements Saveable { if (!isBlockedByShutdown(p.task)) { Runnable runnable = makeFlyWeightTaskBuildable(p); - + LOGGER.log(Level.FINE, "Converting flyweight task: {0} into a BuildableRunnable", p.task.getFullDisplayName()); if(runnable != null){ return runnable; } @@ -1551,9 +1570,11 @@ public class Queue extends ResourceController implements Saveable { //if the execution gets here, it means the task could not be scheduled since the node //the task is supposed to run on is offline or not available. //Thus, the flyweighttask enters the buildables queue and will ask Jenkins to provision a node + LOGGER.log(Level.FINEST, "Flyweight task {0} is entering as buildable to provision a node.", p.task.getFullDisplayName()); return new BuildableRunnable(p); } // if the execution gets here, it means the task is blocked by shutdown and null is returned. + LOGGER.log(Level.FINE, "Task {0} is blocked by shutdown.", p.task.getFullDisplayName()); return null; } else { // regular heavyweight task @@ -1595,6 +1616,8 @@ public class Queue extends ResourceController implements Saveable { if (n.canTake(p) != null) { continue; } + + LOGGER.log(Level.FINE, "Creating flyweight task {0} for machine {1}", new Object[]{p.task, c.getName()}); return new Runnable() { @Override public void run() { c.startFlyWeightTask(new WorkUnitContext(p).createWorkUnit(p.task)); From 8d897edfdf6e20c726af5a1501770c4f656abd22 Mon Sep 17 00:00:00 2001 From: christ66 Date: Mon, 12 Oct 2015 01:21:22 -0700 Subject: [PATCH 02/76] Fixed incomplete log message where there is a potential candidate for a task. --- core/src/main/java/hudson/model/Queue.java | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/core/src/main/java/hudson/model/Queue.java b/core/src/main/java/hudson/model/Queue.java index cba47d30a2..e751b536fe 100644 --- a/core/src/main/java/hudson/model/Queue.java +++ b/core/src/main/java/hudson/model/Queue.java @@ -1504,7 +1504,9 @@ public class Queue extends ResourceController implements Saveable { List candidates = new ArrayList(parked.size()); for (JobOffer j : parked.values()) { if (j.canTake(p)) { - LOGGER.log(Level.FINEST, "Potential candidate for "); + LOGGER.log(Level.FINEST, + "{0} is a potential candidate for task {1}", + new Object[]{j.executor.getDisplayName(), p.task.getFullDisplayName()}); candidates.add(j); } } From 5164133c9bebbb550ddca36585293a3dfd5a5bd0 Mon Sep 17 00:00:00 2001 From: christ66 Date: Mon, 12 Oct 2015 01:24:16 -0700 Subject: [PATCH 03/76] Change from printing the task object to the full display name. --- core/src/main/java/hudson/model/Queue.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/core/src/main/java/hudson/model/Queue.java b/core/src/main/java/hudson/model/Queue.java index e751b536fe..e365b4923f 100644 --- a/core/src/main/java/hudson/model/Queue.java +++ b/core/src/main/java/hudson/model/Queue.java @@ -1619,7 +1619,7 @@ public class Queue extends ResourceController implements Saveable { continue; } - LOGGER.log(Level.FINE, "Creating flyweight task {0} for machine {1}", new Object[]{p.task, c.getName()}); + LOGGER.log(Level.FINE, "Creating flyweight task {0} for computer {1}", new Object[]{p.task.getFullDisplayName(), c.getName()}); return new Runnable() { @Override public void run() { c.startFlyWeightTask(new WorkUnitContext(p).createWorkUnit(p.task)); From 8ef443d57f0229d7a91b24d4d2d451104897d2e9 Mon Sep 17 00:00:00 2001 From: christ66 Date: Mon, 12 Oct 2015 01:33:18 -0700 Subject: [PATCH 04/76] Reduce the amount of times Task.getFullDisplayName is invoked. --- core/src/main/java/hudson/model/Queue.java | 27 +++++++++++++--------- 1 file changed, 16 insertions(+), 11 deletions(-) diff --git a/core/src/main/java/hudson/model/Queue.java b/core/src/main/java/hudson/model/Queue.java index e365b4923f..af11e8cd80 100644 --- a/core/src/main/java/hudson/model/Queue.java +++ b/core/src/main/java/hudson/model/Queue.java @@ -1423,11 +1423,12 @@ public class Queue extends ResourceController implements Saveable { Collections.sort(blockedItems, QueueSorter.DEFAULT_BLOCKED_ITEM_COMPARATOR); } for (BlockedItem p : blockedItems) { - LOGGER.log(Level.FINER, "Current blocked item: {0}", p.task.getFullDisplayName()); + String taskDisplayName = p.task.getFullDisplayName(); + LOGGER.log(Level.FINER, "Current blocked item: {0}", taskDisplayName); if (!isBuildBlocked(p) && allowNewBuildableTask(p.task)) { LOGGER.log(Level.INFO, "BlockedItem {0}: blocked -> buildable as the build is not blocked and new tasks are allowed", - p.task.getFullDisplayName()); + taskDisplayName); // ready to be executed Runnable r = makeBuildable(new BuildableItem(p)); @@ -1457,11 +1458,12 @@ public class Queue extends ResourceController implements Saveable { if (!isBuildBlocked(top) && allowNewBuildableTask(p)) { // ready to be executed immediately Runnable r = makeBuildable(new BuildableItem(top)); + String topTaskDisplayName = top.task.getFullDisplayName(); if (r != null) { - LOGGER.log(Level.FINE, "Executing runnable {0}", top.task.getFullDisplayName()); + LOGGER.log(Level.FINE, "Executing runnable {0}", topTaskDisplayName); r.run(); } else { - LOGGER.log(Level.FINEST, "Item {0} was unable to be made a buildable and is now a blocked item.", top.task.getFullDisplayName()); + LOGGER.log(Level.FINEST, "Item {0} was unable to be made a buildable and is now a blocked item.", topTaskDisplayName); new BlockedItem(top).enter(this); } } else { @@ -1491,11 +1493,13 @@ public class Queue extends ResourceController implements Saveable { continue; } + String taskDisplayName = p.task.getFullDisplayName(); + if (p.task instanceof FlyweightTask) { Runnable r = makeFlyWeightTaskBuildable(new BuildableItem(p)); if (r != null) { p.leave(this); - LOGGER.log(Level.FINEST, "Executing flyweight task {0}", p.task.getFullDisplayName()); + LOGGER.log(Level.FINEST, "Executing flyweight task {0}", taskDisplayName); r.run(); updateSnapshot(); } @@ -1506,7 +1510,7 @@ public class Queue extends ResourceController implements Saveable { if (j.canTake(p)) { LOGGER.log(Level.FINEST, "{0} is a potential candidate for task {1}", - new Object[]{j.executor.getDisplayName(), p.task.getFullDisplayName()}); + new Object[]{j.executor.getDisplayName(), taskDisplayName}); candidates.add(j); } } @@ -1524,12 +1528,12 @@ public class Queue extends ResourceController implements Saveable { // found a matching executor. use it. WorkUnitContext wuc = new WorkUnitContext(p); - LOGGER.log(Level.FINER, "Found a matching executor for {0}. Using it.", p.task.getFullDisplayName()); + LOGGER.log(Level.FINER, "Found a matching executor for {0}. Using it.", taskDisplayName); m.execute(wuc); p.leave(this); if (!wuc.getWorkUnits().isEmpty()) { - LOGGER.log(Level.FINE, "BuildableItem {0} marked as pending.", p.task.getFullDisplayName()); + LOGGER.log(Level.FINE, "BuildableItem {0} marked as pending.", taskDisplayName); makePending(p); } else @@ -1560,10 +1564,11 @@ public class Queue extends ResourceController implements Saveable { */ private @CheckForNull Runnable makeBuildable(final BuildableItem p) { if (p.task instanceof FlyweightTask) { + String taskDisplayName = p.task.getFullDisplayName(); if (!isBlockedByShutdown(p.task)) { Runnable runnable = makeFlyWeightTaskBuildable(p); - LOGGER.log(Level.FINE, "Converting flyweight task: {0} into a BuildableRunnable", p.task.getFullDisplayName()); + LOGGER.log(Level.FINE, "Converting flyweight task: {0} into a BuildableRunnable", taskDisplayName); if(runnable != null){ return runnable; } @@ -1572,11 +1577,11 @@ public class Queue extends ResourceController implements Saveable { //if the execution gets here, it means the task could not be scheduled since the node //the task is supposed to run on is offline or not available. //Thus, the flyweighttask enters the buildables queue and will ask Jenkins to provision a node - LOGGER.log(Level.FINEST, "Flyweight task {0} is entering as buildable to provision a node.", p.task.getFullDisplayName()); + LOGGER.log(Level.FINEST, "Flyweight task {0} is entering as buildable to provision a node.", taskDisplayName); return new BuildableRunnable(p); } // if the execution gets here, it means the task is blocked by shutdown and null is returned. - LOGGER.log(Level.FINE, "Task {0} is blocked by shutdown.", p.task.getFullDisplayName()); + LOGGER.log(Level.FINE, "Task {0} is blocked by shutdown.", taskDisplayName); return null; } else { // regular heavyweight task From 09fadd58b56f8504fab414a9414d081918461d1a Mon Sep 17 00:00:00 2001 From: christ66 Date: Mon, 12 Oct 2015 16:37:18 -0700 Subject: [PATCH 05/76] Use Level.FINEST for logging all queue information. --- core/src/main/java/hudson/model/Queue.java | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/core/src/main/java/hudson/model/Queue.java b/core/src/main/java/hudson/model/Queue.java index af11e8cd80..d6e1c79d5c 100644 --- a/core/src/main/java/hudson/model/Queue.java +++ b/core/src/main/java/hudson/model/Queue.java @@ -1424,9 +1424,9 @@ public class Queue extends ResourceController implements Saveable { } for (BlockedItem p : blockedItems) { String taskDisplayName = p.task.getFullDisplayName(); - LOGGER.log(Level.FINER, "Current blocked item: {0}", taskDisplayName); + LOGGER.log(Level.FINEST, "Current blocked item: {0}", taskDisplayName); if (!isBuildBlocked(p) && allowNewBuildableTask(p.task)) { - LOGGER.log(Level.INFO, + LOGGER.log(Level.FINEST, "BlockedItem {0}: blocked -> buildable as the build is not blocked and new tasks are allowed", taskDisplayName); @@ -1449,7 +1449,7 @@ public class Queue extends ResourceController implements Saveable { WaitingItem top = peek(); if (top.timestamp.compareTo(new GregorianCalendar()) > 0) { - LOGGER.log(Level.FINE, "Finished moving all ready items from queue."); + LOGGER.log(Level.FINEST, "Finished moving all ready items from queue."); break; // finished moving all ready items from queue } @@ -1460,7 +1460,7 @@ public class Queue extends ResourceController implements Saveable { Runnable r = makeBuildable(new BuildableItem(top)); String topTaskDisplayName = top.task.getFullDisplayName(); if (r != null) { - LOGGER.log(Level.FINE, "Executing runnable {0}", topTaskDisplayName); + LOGGER.log(Level.FINEST, "Executing runnable {0}", topTaskDisplayName); r.run(); } else { LOGGER.log(Level.FINEST, "Item {0} was unable to be made a buildable and is now a blocked item.", topTaskDisplayName); @@ -1528,16 +1528,16 @@ public class Queue extends ResourceController implements Saveable { // found a matching executor. use it. WorkUnitContext wuc = new WorkUnitContext(p); - LOGGER.log(Level.FINER, "Found a matching executor for {0}. Using it.", taskDisplayName); + LOGGER.log(Level.FINEST, "Found a matching executor for {0}. Using it.", taskDisplayName); m.execute(wuc); p.leave(this); if (!wuc.getWorkUnits().isEmpty()) { - LOGGER.log(Level.FINE, "BuildableItem {0} marked as pending.", taskDisplayName); + LOGGER.log(Level.FINEST, "BuildableItem {0} marked as pending.", taskDisplayName); makePending(p); } else - LOGGER.log(Level.FINE, "BuildableItem {0} with empty work units!?", p); + LOGGER.log(Level.FINEST, "BuildableItem {0} with empty work units!?", p); // Ensure that identification of blocked tasks is using the live state: JENKINS-27708 & JENKINS-27871 // The creation of a snapshot itself should be relatively cheap given the expected rate of @@ -1568,7 +1568,7 @@ public class Queue extends ResourceController implements Saveable { if (!isBlockedByShutdown(p.task)) { Runnable runnable = makeFlyWeightTaskBuildable(p); - LOGGER.log(Level.FINE, "Converting flyweight task: {0} into a BuildableRunnable", taskDisplayName); + LOGGER.log(Level.FINEST, "Converting flyweight task: {0} into a BuildableRunnable", taskDisplayName); if(runnable != null){ return runnable; } @@ -1581,7 +1581,7 @@ public class Queue extends ResourceController implements Saveable { return new BuildableRunnable(p); } // if the execution gets here, it means the task is blocked by shutdown and null is returned. - LOGGER.log(Level.FINE, "Task {0} is blocked by shutdown.", taskDisplayName); + LOGGER.log(Level.FINEST, "Task {0} is blocked by shutdown.", taskDisplayName); return null; } else { // regular heavyweight task @@ -1624,7 +1624,7 @@ public class Queue extends ResourceController implements Saveable { continue; } - LOGGER.log(Level.FINE, "Creating flyweight task {0} for computer {1}", new Object[]{p.task.getFullDisplayName(), c.getName()}); + LOGGER.log(Level.FINEST, "Creating flyweight task {0} for computer {1}", new Object[]{p.task.getFullDisplayName(), c.getName()}); return new Runnable() { @Override public void run() { c.startFlyWeightTask(new WorkUnitContext(p).createWorkUnit(p.task)); From a877ca6e3c9ae46515b297baa921afaca7447d98 Mon Sep 17 00:00:00 2001 From: Kohsuke Kawaguchi Date: Wed, 11 Nov 2015 06:10:16 -0800 Subject: [PATCH 06/76] [maven-release-plugin] prepare release jenkins-1.625.2 --- cli/pom.xml | 2 +- core/pom.xml | 2 +- plugins/pom.xml | 10 +++++----- pom.xml | 4 ++-- test/pom.xml | 2 +- war/pom.xml | 2 +- 6 files changed, 11 insertions(+), 11 deletions(-) diff --git a/cli/pom.xml b/cli/pom.xml index d67058f6c1..0fd72014fb 100644 --- a/cli/pom.xml +++ b/cli/pom.xml @@ -5,7 +5,7 @@ org.jenkins-ci.main pom - 1.625.2-SNAPSHOT + 1.625.2 cli diff --git a/core/pom.xml b/core/pom.xml index 336c8a850a..c3b6b34026 100644 --- a/core/pom.xml +++ b/core/pom.xml @@ -29,7 +29,7 @@ THE SOFTWARE. org.jenkins-ci.main pom - 1.625.2-SNAPSHOT + 1.625.2 jenkins-core diff --git a/plugins/pom.xml b/plugins/pom.xml index 4114c5e044..04ea545fe7 100644 --- a/plugins/pom.xml +++ b/plugins/pom.xml @@ -12,7 +12,7 @@ org.jenkins-ci.plugins plugin Jenkins plugin POM - 1.625.2-SNAPSHOT + 1.625.2 pom From 7fdb589133de09e77d29397ee01bcc9004e25cb2 Mon Sep 17 00:00:00 2001 From: tfennelly Date: Wed, 18 Nov 2015 11:36:30 +0000 Subject: [PATCH 15/76] Handle YUI submit