From 6ca8f9c80ed4bfcdfa2330b53778c7287c9f9b2b Mon Sep 17 00:00:00 2001 From: Tomek Szmytka Date: Sat, 29 Aug 2020 13:04:11 +0200 Subject: [PATCH 1/4] #200 Use a separate action for indicating currently running job and its color map name. Recognize it while rendering --- .../plugins/ansicolor/AnsiColorStep.java | 9 +++++++ .../ansicolor/ColorConsoleAnnotator.java | 1 + .../ansicolor/action/ColorizedAction.java | 24 +++++++++++++++++-- 3 files changed, 32 insertions(+), 2 deletions(-) diff --git a/src/main/java/hudson/plugins/ansicolor/AnsiColorStep.java b/src/main/java/hudson/plugins/ansicolor/AnsiColorStep.java index fb53bd5..77aeefd 100644 --- a/src/main/java/hudson/plugins/ansicolor/AnsiColorStep.java +++ b/src/main/java/hudson/plugins/ansicolor/AnsiColorStep.java @@ -72,6 +72,7 @@ private static class ExecutionImpl extends AbstractStepExecutionImpl { @Override public boolean start() throws Exception { StepContext context = getContext(); + EnvironmentExpander currentEnvironment = context.get(EnvironmentExpander.class); EnvironmentExpander terminalEnvironment = EnvironmentExpander.constant(Collections.singletonMap("TERM", colorMapName)); context.newBodyInvoker() @@ -157,6 +158,14 @@ private void issueAction(StepContext context, ColorizedAction action) { run.addAction(action); taskListener.annotate(new ActionNote(action)); ensureRendering(taskListener); + final ColorizedAction currentAction = new ColorizedAction(action.getColorMapName(), ColorizedAction.Command.CURRENT); + if (action.getCommand().equals(ColorizedAction.Command.START)) { + run.addOrReplaceAction(currentAction); + } else { + run.removeAction(currentAction); + } + run.getId(); + } } catch (IOException | InterruptedException e) { LOGGER.log(Level.WARNING, "Could not annotate. Ansicolor plugin will not work correctly.", e); diff --git a/src/main/java/hudson/plugins/ansicolor/ColorConsoleAnnotator.java b/src/main/java/hudson/plugins/ansicolor/ColorConsoleAnnotator.java index aaf7b9a..133a4a6 100644 --- a/src/main/java/hudson/plugins/ansicolor/ColorConsoleAnnotator.java +++ b/src/main/java/hudson/plugins/ansicolor/ColorConsoleAnnotator.java @@ -88,6 +88,7 @@ public ConsoleAnnotator annotate(@Nonnull Object context, @Nonnull Marku : ColorizedAction.parseAction(text, run); switch (colorizedAction.getCommand()) { case START: + case CURRENT: colorMapName = colorizedAction.getColorMapName(); break; case STOP: diff --git a/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java b/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java index a6e4969..fd3df0d 100644 --- a/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java +++ b/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java @@ -29,6 +29,7 @@ import hudson.model.Run; import hudson.plugins.ansicolor.AnsiColorMap; +import java.util.Optional; import java.util.UUID; import static hudson.plugins.ansicolor.action.ActionNote.TAG_ACTION_BEGIN; @@ -48,10 +49,18 @@ public class ColorizedAction extends InvisibleAction { private final Command command; public enum Command { + /** + * + */ START, STOP, CONTINUE, - IGNORE + IGNORE, + + /** + * Currently running execution + */ + CURRENT } public ColorizedAction(String colorMapName, Command command) { @@ -87,7 +96,18 @@ public static ColorizedAction parseAction(MarkupText text, Run run) { final String id = line.substring(from, to); return run.getActions(ColorizedAction.class).stream().filter(a -> id.equals(a.getId())).findAny().orElse(CONTINUE); } - return line.contains(TAG_PIPELINE_INTERNAL) ? IGNORE : CONTINUE; + if (line.contains(TAG_PIPELINE_INTERNAL)) { + return IGNORE; + } + if (run.isBuilding()) { + Optional currentAction = run.getActions(ColorizedAction.class).stream() + .filter(a -> Command.CURRENT.equals(a.getCommand())) + .findFirst(); + if (currentAction.isPresent()) { + return currentAction.get(); + } + } + return CONTINUE; } public static ColorizedAction parseAction(String lineContent, long lineNo, Run run, LineIdentifier lineIdentifier) { From 54eaaabc0cdea09c87a6bf7cefe932888c470544 Mon Sep 17 00:00:00 2001 From: Tomek Szmytka Date: Sat, 29 Aug 2020 22:15:21 +0200 Subject: [PATCH 2/4] #200 Use action with command current to indicate a job that is currently running. Use it to render long log. Test --- pom.xml | 6 ++++ .../plugins/ansicolor/AnsiColorStep.java | 4 +-- .../ansicolor/action/ColorizedAction.java | 5 +-- .../plugins/ansicolor/AnsiColorStepTest.java | 33 +++++++++++++++++-- .../ansicolor/ColorConsoleAnnotatorTest.java | 3 ++ .../plugins/ansicolor/JenkinsTestSupport.java | 2 +- .../ansicolor/action/ColorizedActionTest.java | 30 +++++++++++++++++ 7 files changed, 73 insertions(+), 10 deletions(-) diff --git a/pom.xml b/pom.xml index f8848ee..4c75108 100644 --- a/pom.xml +++ b/pom.xml @@ -93,6 +93,12 @@ 3.16.1 test + + org.awaitility + awaitility + 4.0.3 + test + diff --git a/src/main/java/hudson/plugins/ansicolor/AnsiColorStep.java b/src/main/java/hudson/plugins/ansicolor/AnsiColorStep.java index 77aeefd..75eb537 100644 --- a/src/main/java/hudson/plugins/ansicolor/AnsiColorStep.java +++ b/src/main/java/hudson/plugins/ansicolor/AnsiColorStep.java @@ -160,12 +160,10 @@ private void issueAction(StepContext context, ColorizedAction action) { ensureRendering(taskListener); final ColorizedAction currentAction = new ColorizedAction(action.getColorMapName(), ColorizedAction.Command.CURRENT); if (action.getCommand().equals(ColorizedAction.Command.START)) { - run.addOrReplaceAction(currentAction); + run.addAction(currentAction); } else { run.removeAction(currentAction); } - run.getId(); - } } catch (IOException | InterruptedException e) { LOGGER.log(Level.WARNING, "Could not annotate. Ansicolor plugin will not work correctly.", e); diff --git a/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java b/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java index fd3df0d..7d3d20e 100644 --- a/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java +++ b/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java @@ -49,16 +49,13 @@ public class ColorizedAction extends InvisibleAction { private final Command command; public enum Command { - /** - * - */ START, STOP, CONTINUE, IGNORE, /** - * Currently running execution + * The running job's current action containing current color map name */ CURRENT } diff --git a/src/test/java/hudson/plugins/ansicolor/AnsiColorStepTest.java b/src/test/java/hudson/plugins/ansicolor/AnsiColorStepTest.java index 00858f0..8c7ac23 100644 --- a/src/test/java/hudson/plugins/ansicolor/AnsiColorStepTest.java +++ b/src/test/java/hudson/plugins/ansicolor/AnsiColorStepTest.java @@ -1,5 +1,6 @@ package hudson.plugins.ansicolor; +import hudson.model.queue.QueueTaskFuture; import org.jenkinsci.plugins.workflow.cps.CpsFlowDefinition; import org.jenkinsci.plugins.workflow.job.WorkflowJob; import org.jenkinsci.plugins.workflow.job.WorkflowRun; @@ -13,13 +14,14 @@ import org.jvnet.hudson.test.RestartableJenkinsRule; import java.io.StringWriter; +import java.time.Duration; import java.util.Arrays; import java.util.Collection; import java.util.logging.Level; import static org.assertj.core.api.Assertions.assertThat; -import static org.junit.Assert.assertEquals; -import static org.junit.Assert.assertTrue; +import static org.awaitility.Awaitility.await; +import static org.junit.Assert.*; public class AnsiColorStepTest { @@ -136,6 +138,33 @@ public void willNotLeakFormattingToMetadataLines() { ); } + @Issue("200") + @Test + public void canRenderLongOutputWhileBuildStillRunning() { + story.addStep(new Statement() { + + @Override + public void evaluate() throws Throwable { + final String a1k = JenkinsTestSupport.repeat("a", 1024); + final String script = "ansiColor('xterm') {\n" + + JenkinsTestSupport.repeat("echo '\033[32m" + a1k + "\033[0m'\n", 150) + + "}"; + final WorkflowJob project = story.j.jenkins.createProject(WorkflowJob.class, "canRenderLongOutputWhileBuildStillRunning"); + project.setDefinition(new CpsFlowDefinition(script, true)); + QueueTaskFuture runFuture = project.scheduleBuild2(0); + assertNotNull(runFuture); + final WorkflowRun lastBuild = runFuture.waitForStart(); + await().pollDelay(Duration.ofSeconds(10)).pollInterval(Duration.ofSeconds(5)).atMost(Duration.ofSeconds(60)).until(() -> { + StringWriter writer = new StringWriter(); + final int skipInitialStartAction = 3000; + assertTrue(lastBuild.getLogText().writeHtmlTo(skipInitialStartAction, writer) > 0); + final String html = writer.toString().replaceAll("", ""); + return !runFuture.isDone() && html.contains("" + a1k + "") && !html.contains("\033[32m"); + }); + } + }); + } + private void assertOutputOnRunningPipeline(Collection expectedOutput, Collection notExpectedOutput, String pipelineScript) { story.addStep(new Statement() { diff --git a/src/test/java/hudson/plugins/ansicolor/ColorConsoleAnnotatorTest.java b/src/test/java/hudson/plugins/ansicolor/ColorConsoleAnnotatorTest.java index 6596e0e..63db219 100644 --- a/src/test/java/hudson/plugins/ansicolor/ColorConsoleAnnotatorTest.java +++ b/src/test/java/hudson/plugins/ansicolor/ColorConsoleAnnotatorTest.java @@ -3,6 +3,7 @@ import jenkins.model.Jenkins; import org.jenkinsci.plugins.workflow.cps.CpsFlowDefinition; import org.jenkinsci.plugins.workflow.job.WorkflowJob; +import org.jenkinsci.plugins.workflow.job.WorkflowRun; import org.junit.ClassRule; import org.junit.Rule; import org.junit.Test; @@ -11,9 +12,11 @@ import org.jvnet.hudson.test.LoggerRule; import org.jvnet.hudson.test.RestartableJenkinsRule; +import java.io.File; import java.io.StringWriter; import java.util.logging.Level; +import static org.assertj.core.api.Assertions.assertThat; import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertTrue; diff --git a/src/test/java/hudson/plugins/ansicolor/JenkinsTestSupport.java b/src/test/java/hudson/plugins/ansicolor/JenkinsTestSupport.java index a67b683..0fc6259 100644 --- a/src/test/java/hudson/plugins/ansicolor/JenkinsTestSupport.java +++ b/src/test/java/hudson/plugins/ansicolor/JenkinsTestSupport.java @@ -45,7 +45,7 @@ public void evaluate() throws Throwable { }); } - protected static String repeat(String s, int times) { + public static String repeat(String s, int times) { return IntStream.range(0, times).mapToObj(i -> s).collect(Collectors.joining()); } } diff --git a/src/test/java/hudson/plugins/ansicolor/action/ColorizedActionTest.java b/src/test/java/hudson/plugins/ansicolor/action/ColorizedActionTest.java index b62382b..817c124 100644 --- a/src/test/java/hudson/plugins/ansicolor/action/ColorizedActionTest.java +++ b/src/test/java/hudson/plugins/ansicolor/action/ColorizedActionTest.java @@ -25,6 +25,7 @@ public class ColorizedActionTest { private static final ColorizedAction ACTION_2 = new ColorizedAction("map0", ColorizedAction.Command.STOP); private static final ColorizedAction ACTION_3 = new ColorizedAction("map3", ColorizedAction.Command.START); private static final ColorizedAction ACTION_4 = new ColorizedAction("map3", ColorizedAction.Command.STOP); + private static final ColorizedAction ACTION_5 = new ColorizedAction("map0", ColorizedAction.Command.CURRENT); private ColorizedAction colorizedAction; @@ -34,6 +35,9 @@ public class ColorizedActionTest { @Mock private FreeStyleBuild buildRunMultipleStarts; + @Mock + private FreeStyleBuild buildRunOneCurrent; + @Before public void setUp() throws Exception { when(buildRunSingleStart.getActions(eq(ColorizedAction.class))).thenReturn(Arrays.asList( @@ -48,6 +52,11 @@ public void setUp() throws Exception { ACTION_3, ACTION_4 )); + when(buildRunOneCurrent.getActions(eq(ColorizedAction.class))).thenReturn(Arrays.asList( + ACTION_0, + ACTION_5 + )); + colorizedAction = new ColorizedAction("vga", ColorizedAction.Command.START); } @@ -113,4 +122,25 @@ public void willReturnCommandIgnoreOnPipelineInternalLineMultipleStarts() { final ColorizedAction colorizedAction = ColorizedAction.parseAction(markupText, buildRunMultipleStarts); assertEquals(ColorizedAction.Command.IGNORE, colorizedAction.getCommand()); } + + @Test + public void canParseActionCurrentWhileBuildRunning() { + when(buildRunOneCurrent.isBuilding()).thenReturn(true); + final MarkupText markupText = new MarkupText("Log line"); + assertEquals(ACTION_5, ColorizedAction.parseAction(markupText, buildRunOneCurrent)); + } + + @Test + public void wontParseActionCurrentWhileBuildNotRunning() { + when(buildRunOneCurrent.isBuilding()).thenReturn(false); + final MarkupText markupText = new MarkupText("Log line"); + assertEquals(CONTINUE, ColorizedAction.parseAction(markupText, buildRunOneCurrent)); + } + + @Test + public void wontParseActionCurrentWhileBuildRunningButNoCurrentAction() { + when(buildRunSingleStart.isBuilding()).thenReturn(true); + final MarkupText markupText = new MarkupText("Log line"); + assertEquals(CONTINUE, ColorizedAction.parseAction(markupText, buildRunSingleStart)); + } } From c3b164507be3755818c7610583ffff1d99454c5d Mon Sep 17 00:00:00 2001 From: Tomek Szmytka Date: Sun, 30 Aug 2020 18:30:07 +0200 Subject: [PATCH 3/4] #200 Use hamcrest provided by jenkins-test-harness --- pom.xml | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/pom.xml b/pom.xml index 4c75108..6caa6b6 100644 --- a/pom.xml +++ b/pom.xml @@ -98,6 +98,12 @@ awaitility 4.0.3 test + + + org.hamcrest + hamcrest + + From c4ccad56a9beb74e3baa479e65d7107da3707213 Mon Sep 17 00:00:00 2001 From: Tomek Szmytka Date: Sun, 30 Aug 2020 20:40:42 +0200 Subject: [PATCH 4/4] Debug test failing on remote CI host Debug test failing on remote CI host Debug test failing on remote CI host Debug test failing on remote CI host Debug test failing on remote CI host Clean up debugging Increase lines to make it run longer. Test completes sometimes Consistently use 'LOGGER' Document change --- CHANGELOG.md | 1 + .../plugins/ansicolor/AnsiColorBuildWrapper.java | 1 + .../plugins/ansicolor/AnsiColorConsoleLogFilter.java | 10 +++++----- .../plugins/ansicolor/action/ColorizedAction.java | 6 +++++- .../hudson/plugins/ansicolor/AnsiColorStepTest.java | 6 ++++-- 5 files changed, 16 insertions(+), 8 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 7b3928d..ecbc1d4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,7 @@ 0.7.3 (Next) ============ +* [#202](https://github.com/jenkinsci/ansicolor-plugin/pull/202): Render logs correctly for long running jobs which generate lots of output - [@tszmytka](https://github.com/tszmytka). * Your contribution here. diff --git a/src/main/java/hudson/plugins/ansicolor/AnsiColorBuildWrapper.java b/src/main/java/hudson/plugins/ansicolor/AnsiColorBuildWrapper.java index d478a1f..af4babd 100644 --- a/src/main/java/hudson/plugins/ansicolor/AnsiColorBuildWrapper.java +++ b/src/main/java/hudson/plugins/ansicolor/AnsiColorBuildWrapper.java @@ -64,6 +64,7 @@ public final class AnsiColorBuildWrapper extends SimpleBuildWrapper implements S /** * Create a new {@link AnsiColorBuildWrapper}. + * @param colorMapName Name of the color map to use */ @DataBoundConstructor public AnsiColorBuildWrapper(String colorMapName) { diff --git a/src/main/java/hudson/plugins/ansicolor/AnsiColorConsoleLogFilter.java b/src/main/java/hudson/plugins/ansicolor/AnsiColorConsoleLogFilter.java index 4e48859..3a81241 100644 --- a/src/main/java/hudson/plugins/ansicolor/AnsiColorConsoleLogFilter.java +++ b/src/main/java/hudson/plugins/ansicolor/AnsiColorConsoleLogFilter.java @@ -24,7 +24,7 @@ public final class AnsiColorConsoleLogFilter extends ConsoleLogFilter implements private static final long serialVersionUID = 1L; - private static final Logger LOG = Logger.getLogger(AnsiColorConsoleLogFilter.class.getName()); + private static final Logger LOGGER = Logger.getLogger(AnsiColorConsoleLogFilter.class.getName()); private AnsiColorMap colorMap; private final Map notes; @@ -46,14 +46,14 @@ public AnsiColorConsoleLogFilter(AnsiColorMap colorMap) { pregenerateNote(AnsiAttributeElement.framed()); pregenerateNote(AnsiAttributeElement.overline()); // TODO other cases, and other methods - LOG.log(Level.FINE, "Notes pregenerated for {0}", notes.keySet()); + LOGGER.log(Level.FINE, "Notes pregenerated for {0}", notes.keySet()); } - + private void pregenerateNote(AnsiAttributeElement element) { element.emitOpen(html -> pregenerateNote(html)); element.emitClose(html -> pregenerateNote(html)); } - + private void pregenerateNote(String html) { if (!notes.containsKey(html)) { JenkinsJVM.checkJenkinsJVM(); @@ -91,7 +91,7 @@ public void emitHtml(@Nonnull String html) { new SimpleHtmlNote(html).encodeTo(logger); } } catch (IOException e) { - LOG.log(Level.WARNING, "Failed to add HTML markup '" + html + "'", e); + LOGGER.log(Level.WARNING, "Failed to add HTML markup '" + html + "'", e); } } }); diff --git a/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java b/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java index 7d3d20e..6a08cfd 100644 --- a/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java +++ b/src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java @@ -31,6 +31,7 @@ import java.util.Optional; import java.util.UUID; +import java.util.logging.Logger; import static hudson.plugins.ansicolor.action.ActionNote.TAG_ACTION_BEGIN; @@ -38,6 +39,7 @@ * Action for issuing commands to ColorConsoleAnnotator */ public class ColorizedAction extends InvisibleAction { + private static final Logger LOGGER = Logger.getLogger(ColorizedAction.class.getName()); private static final String TAG_PIPELINE_INTERNAL = " run) { if (line.contains(TAG_PIPELINE_INTERNAL)) { return IGNORE; } - if (run.isBuilding()) { + final boolean isBuilding = run.isBuilding(); + LOGGER.fine("Run is building: " + isBuilding); + if (isBuilding) { Optional currentAction = run.getActions(ColorizedAction.class).stream() .filter(a -> Command.CURRENT.equals(a.getCommand())) .findFirst(); diff --git a/src/test/java/hudson/plugins/ansicolor/AnsiColorStepTest.java b/src/test/java/hudson/plugins/ansicolor/AnsiColorStepTest.java index 8c7ac23..69b0b55 100644 --- a/src/test/java/hudson/plugins/ansicolor/AnsiColorStepTest.java +++ b/src/test/java/hudson/plugins/ansicolor/AnsiColorStepTest.java @@ -147,14 +147,16 @@ public void canRenderLongOutputWhileBuildStillRunning() { public void evaluate() throws Throwable { final String a1k = JenkinsTestSupport.repeat("a", 1024); final String script = "ansiColor('xterm') {\n" + - JenkinsTestSupport.repeat("echo '\033[32m" + a1k + "\033[0m'\n", 150) + + "for (i = 0; i < 1000; i++) {" + + "echo '\033[32m" + a1k + "\033[0m'\n" + + "}" + "}"; final WorkflowJob project = story.j.jenkins.createProject(WorkflowJob.class, "canRenderLongOutputWhileBuildStillRunning"); project.setDefinition(new CpsFlowDefinition(script, true)); QueueTaskFuture runFuture = project.scheduleBuild2(0); assertNotNull(runFuture); final WorkflowRun lastBuild = runFuture.waitForStart(); - await().pollDelay(Duration.ofSeconds(10)).pollInterval(Duration.ofSeconds(5)).atMost(Duration.ofSeconds(60)).until(() -> { + await().pollInterval(Duration.ofSeconds(5)).atMost(Duration.ofSeconds(150)).until(() -> { StringWriter writer = new StringWriter(); final int skipInitialStartAction = 3000; assertTrue(lastBuild.getLogText().writeHtmlTo(skipInitialStartAction, writer) > 0);