Render logs correctly for long running jobs which generate lots of logs

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.
 
 

pom.xml

@@ -93,6 +93,18 @@
       <version>3.16.1</version>
       <scope>test</scope>
     </dependency>
+    <dependency>
+      <groupId>org.awaitility</groupId>
+      <artifactId>awaitility</artifactId>
+      <version>4.0.3</version>
+      <scope>test</scope>
+      <exclusions>
+        <exclusion>
+          <groupId>org.hamcrest</groupId>
+          <artifactId>hamcrest</artifactId>
+        </exclusion>
+      </exclusions>
+    </dependency>
 
   </dependencies>
   <dependencyManagement>

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) {

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<String, byte[]> 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);
                 }
             }
         });

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,12 @@ 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.addAction(currentAction);
+                    } else {
+                        run.removeAction(currentAction);
+                    }
                 }
             } catch (IOException | InterruptedException e) {
                 LOGGER.log(Level.WARNING, "Could not annotate. Ansicolor plugin will not work correctly.", e);

src/main/java/hudson/plugins/ansicolor/ColorConsoleAnnotator.java

@@ -88,6 +88,7 @@ public ConsoleAnnotator<Object> annotate(@Nonnull Object context, @Nonnull Marku
             : ColorizedAction.parseAction(text, run);
         switch (colorizedAction.getCommand()) {
             case START:
+            case CURRENT:
                 colorMapName = colorizedAction.getColorMapName();
                 break;
             case STOP:

src/main/java/hudson/plugins/ansicolor/action/ColorizedAction.java

@@ -29,14 +29,17 @@
 import hudson.model.Run;
 import hudson.plugins.ansicolor.AnsiColorMap;
 
+import java.util.Optional;
 import java.util.UUID;
+import java.util.logging.Logger;
 
 import static hudson.plugins.ansicolor.action.ActionNote.TAG_ACTION_BEGIN;
 
 /**
  * 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 = "<span class=\"pipeline-new-node\"";
     static final ColorizedAction CONTINUE = new ColorizedAction("", Command.CONTINUE);
     static final ColorizedAction IGNORE = new ColorizedAction("", Command.IGNORE);
@@ -51,7 +54,12 @@ public enum Command {
         START,
         STOP,
         CONTINUE,
-        IGNORE
+        IGNORE,
+
+        /**
+         * The running job's current action containing current color map name
+         */
+        CURRENT
     }
 
     public ColorizedAction(String colorMapName, Command command) {
@@ -87,7 +95,20 @@ 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;
+        }
+        final boolean isBuilding = run.isBuilding();
+        LOGGER.fine("Run is building: " + isBuilding);
+        if (isBuilding) {
+            Optional<ColorizedAction> 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) {

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,35 @@ 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" +
+                    "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<WorkflowRun> runFuture = project.scheduleBuild2(0);
+                assertNotNull(runFuture);
+                final WorkflowRun lastBuild = runFuture.waitForStart();
+                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);
+                    final String html = writer.toString().replaceAll("<!--.+?-->", "");
+                    return !runFuture.isDone() && html.contains("<span style=\"color: #00CD00;\">" + a1k + "</span>") && !html.contains("\033[32m");
+                });
+            }
+        });
+    }
+
     private void assertOutputOnRunningPipeline(Collection<String> expectedOutput, Collection<String> notExpectedOutput, String pipelineScript) {
         story.addStep(new Statement() {
 

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;
 

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());
     }
 }

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));
+    }
 }