Skip to content
This repository has been archived by the owner on Dec 15, 2021. It is now read-only.

Commit

Permalink
Browse files Browse the repository at this point in the history
[FIXED JENKINS-26122] Prepend parallel step execution logs with the b…
…ranch label
  • Loading branch information
tfennelly committed Mar 6, 2015
1 parent 0e956a5 commit 26c0b44
Show file tree
Hide file tree
Showing 5 changed files with 207 additions and 13 deletions.
1 change: 1 addition & 0 deletions CHANGES.md
Expand Up @@ -5,6 +5,7 @@ Only noting significant user-visible or major API changes, not internal code cle
## 1.4 (upcoming)

### User changes
* JENKINS-26122: Prepend `parallel` step execution logs with the branch label.
* JENKINS-26619: _Snippet Generator_ did not work on Git SCM extensions.

## 1.3 (Mar 04 2015)
Expand Down
Expand Up @@ -331,4 +331,68 @@ public void invisibleParallelBranch() throws Exception {
}
});
}

@Test
@Issue("JENKINS-26122")
public void parallelBranchLabels() {
story.addStep(new Statement() {
@Override public void evaluate() throws Throwable {
p = jenkins().createProject(WorkflowJob.class, "demo");
p.setDefinition(new CpsFlowDefinition(join(
"node {\n" +
" parallel( \n" +
" a: { \n" +
" echo('echo a');\n" +
" echo('echo a');\n" +
" }, \n" +
" b: { \n" +
" echo('echo b'); \n" +
" echo('echo b'); \n" +
" }\n" +
" )\n" +
"}\n"
)));

startBuilding().get();
assertBuildCompletedSuccessfully();

// Check that the individual labeled lines are as expected
List<String> logLines = b.getLog(50);
assertGoodLabeledLogs(logLines);

// Check that the logs are printed in the right sequence e.g. that a
// "[a] Running: Print Message" is followed by a "[a] echo a"
assertGoodSequence("a", logLines);
assertGoodSequence("b", logLines);
}
private void assertGoodLabeledLogs(List<String> logLines) {
for (int i = 0; i < logLines.size(); i++) {
String logLine = logLines.get(i);
if (logLine.startsWith("[a] ")) {
assertGoodLabeledLog("a", logLine);
} else if (logLine.startsWith("[b] ")) {
assertGoodLabeledLog("b", logLine);
}
}
}
private void assertGoodLabeledLog(String label, String logLine) {
List<String> possibleLogLines = Arrays.asList(
String.format("[%s] Running: Parallel branch: %s", label, label),
String.format("[%s] Running: Print Message", label),
String.format("[%s] echo %s", label, label)
);
assertTrue(possibleLogLines.contains(logLine));
}
private void assertGoodSequence(String label, List<String> logLines) {
String running = String.format("[%s] Running: Print Message", label);
String echo = String.format("[%s] echo %s", label, label);

for (int i = 0; i < logLines.size() - 1; i++) { // skip the last log line in this loop
if (logLines.get(i).equals(running)) {
assertEquals(echo, logLines.get(i + 1));
}
}
}
});
}
}
@@ -0,0 +1,50 @@
/*
* The MIT License
*
* Copyright (c) 2013-2014, CloudBees, Inc.
*
* Permission is hereby granted, free of charge, to any person obtaining a copy
* of this software and associated documentation files (the "Software"), to deal
* in the Software without restriction, including without limitation the rights
* to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
* copies of the Software, and to permit persons to whom the Software is
* furnished to do so, subject to the following conditions:
*
* The above copyright notice and this permission notice shall be included in
* all copies or substantial portions of the Software.
*
* THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
* IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
* FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
* AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
* LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
* OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
* THE SOFTWARE.
*/
package org.jenkinsci.plugins.workflow.actions;

// TODO: Seems like this should be in the step-api module alongside BodyExecution. Can't go there though because of module dependencies, which I dare not touch :)
// I'd have thought the workflow-api module (where LabelAction lives) would be the one module that all other modules would depend on, but that's not he case.

/**
* Body execution label.
* <p>
* Used to label the branches of an the asynchronous execution represented by a
* BodyExecution.
* </p>
*
* @author <a href="mailto:tom.fennelly@gmail.com">tom.fennelly@gmail.com</a>
*/
public abstract class BodyExecutionLabelAction extends LabelAction {

private final String bodyLabel;

public BodyExecutionLabelAction(String displayName) {
super(displayName);
this.bodyLabel = displayName;
}

public final String getBodyLabel() {
return bodyLabel;
}
}
Expand Up @@ -4,7 +4,7 @@
import groovy.lang.Closure;
import hudson.Extension;
import hudson.model.TaskListener;
import org.jenkinsci.plugins.workflow.actions.LabelAction;
import org.jenkinsci.plugins.workflow.actions.BodyExecutionLabelAction;
import org.jenkinsci.plugins.workflow.cps.CpsVmThreadOnly;
import org.jenkinsci.plugins.workflow.cps.persistence.PersistIn;
import org.jenkinsci.plugins.workflow.steps.BodyExecutionCallback;
Expand Down Expand Up @@ -47,11 +47,11 @@ public StepExecution start(StepContext context) throws Exception {
}

@PersistIn(FLOW_NODE)
public static class ParallelLabelAction extends LabelAction {
public static class ParallelLabelAction extends BodyExecutionLabelAction {
private final String branchName;

ParallelLabelAction(String branchName) {
super(null);
super(branchName);
this.branchName = branchName;
}

Expand Down
Expand Up @@ -24,6 +24,9 @@

package org.jenkinsci.plugins.workflow.job;

import hudson.console.LineTransformationOutputStream;
import org.jenkinsci.plugins.workflow.actions.BodyExecutionLabelAction;
import org.jenkinsci.plugins.workflow.actions.BodyInvocationAction;
import org.jenkinsci.plugins.workflow.actions.TimingAction;
import org.jenkinsci.plugins.workflow.flow.FlowExecutionList;
import com.google.common.util.concurrent.ListenableFuture;
Expand All @@ -50,6 +53,7 @@
import java.io.FileOutputStream;
import java.io.IOException;
import java.io.OutputStream;
import java.io.PrintStream;
import java.nio.charset.Charset;
import java.util.ArrayList;
import java.util.HashMap;
Expand Down Expand Up @@ -243,16 +247,32 @@ private void copyLogs() {
AnnotatedLargeText<? extends FlowNode> logText = la.getLogText();
try {
long old = entry.getValue();
long revised = logText.writeRawLogTo(old, listener.getLogger());
if (revised != old) {
entry.setValue(revised);
modified = true;
OutputStream logger;

String prefix = getLogPrefix(node);
if (prefix != null) {
logger = new LogLinePrefixOutputFilter(listener.getLogger(), "[" + prefix + "] ");
} else {
logger = listener.getLogger();
}
if (logText.isComplete()) {
logText.writeRawLogTo(entry.getValue(), listener.getLogger()); // defend against race condition?
assert !node.isRunning() : "LargeText.complete yet " + node + " claims to still be running";
it.remove();
modified = true;

try {
long revised = logText.writeRawLogTo(old, logger);
if (revised != old) {
entry.setValue(revised);
modified = true;
}
if (logText.isComplete()) {
logText.writeRawLogTo(entry.getValue(), logger); // defend against race condition?
assert !node.isRunning() : "LargeText.complete yet " + node + " claims to still be running";
it.remove();
modified = true;
}
} finally {
if (prefix != null) {
// It's a LogLinePrefixOutputFilter (see above). Force an EOL by closing.
logger.close();
}
}
} catch (IOException x) {
LOGGER.log(Level.WARNING, null, x);
Expand All @@ -272,6 +292,50 @@ private void copyLogs() {
}
}
}

private String getLogPrefix(FlowNode node) {
BodyInvocationAction bodyInvocationAction = node.getAction(BodyInvocationAction.class);

if (bodyInvocationAction != null) {
BodyExecutionLabelAction bodyLabelAction = node.getAction(BodyExecutionLabelAction.class);

if (bodyLabelAction != null) {
return bodyLabelAction.getBodyLabel();
} else {
// This exec body does not have a body label. Stop now.
return null;
}
}

List<FlowNode> parents = node.getParents();
if (parents != null && !parents.isEmpty()) {
for (FlowNode parent : parents) {
String prefix = getLogPrefix(parent);
if (prefix != null) {
return prefix;
}
}
}

return null;
}

protected static final class LogLinePrefixOutputFilter extends LineTransformationOutputStream {

private final PrintStream logger;
private final String prefix;

protected LogLinePrefixOutputFilter(PrintStream logger, String prefix) {
this.logger = logger;
this.prefix = prefix;
}

@Override
protected void eol(byte[] b, int len) throws IOException {
logger.append(prefix);
logger.write(b, 0, len);
}
}

private static final Map<String,WorkflowRun> LOADING_RUNS = new HashMap<String,WorkflowRun>();

Expand Down Expand Up @@ -575,7 +639,7 @@ private final class GraphL implements GraphListener {
}
node.addAction(new TimingAction());

listener.getLogger().println("Running: " + node.getDisplayName());
logNodeMessage(node, "Running: " + node.getDisplayName());
if (node instanceof FlowEndNode) {
finish(((FlowEndNode) node).getResult());
} else {
Expand All @@ -588,6 +652,21 @@ private final class GraphL implements GraphListener {
}
}

private void logNodeMessage(FlowNode node, String message) {
PrintStream logger = listener.getLogger();
String prefix = getLogPrefix(node);
if (prefix != null) {
logger.println(String.format("[%s] %s", prefix, message));
} else {
logger.println(message);
}
// Flushing to keep logs printed in order as much as possible. The copyLogs method uses
// LargeText and possibly LogLinePrefixOutputFilter. Both of these buffer and flush, causing strange
// out of sequence writes to the underlying log stream (and => things being printed out of sequence)
// if we don't flush the logger here.
logger.flush();
}

static void alias() {
Run.XSTREAM2.alias("flow-build", WorkflowRun.class);
new XmlFile(null).getXStream().aliasType("flow-owner", Owner.class); // hack! but how else to set it for arbitrary Descriptor’s?
Expand Down

0 comments on commit 26c0b44

Please sign in to comment.