[FIXED JENKINS-30143] Store elapsed time in timestamp console notes

The timestamp console notes previously relied on the context being a Run, so that they can get the build start time and use it to calculate the elapsed time. The elapsed time is now stored within the console notes during the build. This allows timestamps to be displayed when a different context type is provided, e.g. the workflow plugin provides a StepAtomNode. Builds that ran with an earlier version of Timestamper and an unrecognised context type will now display the system clock timestamps but not the elapsed timestamps, because that information was not recorded.
jenkinsci · Jan 31, 2016 · a774848 · a774848
1 parent 0c20ac3
commit a774848
Show file tree

Hide file tree

Showing 9 changed files with 123 additions and 31 deletions.
diff --git a/src/main/java/hudson/plugins/timestamper/Timestamp.java b/src/main/java/hudson/plugins/timestamper/Timestamp.java
@@ -40,6 +40,11 @@ public final class Timestamp {
    */
   public final long elapsedMillis;
 
+  /**
+   * Whether the elapsed time is known.
+   */
+  public final boolean elapsedMillisKnown;
+
   /**
    * The clock time in milliseconds since midnight, January 1, 1970 UTC.
    */
@@ -54,7 +59,20 @@ public final class Timestamp {
    *          the clock time in milliseconds since midnight, January 1, 1970 UTC
    */
   public Timestamp(long elapsedMillis, long millisSinceEpoch) {
-    this.elapsedMillis = elapsedMillis;
+    this(Long.valueOf(elapsedMillis), millisSinceEpoch);
+  }
+
+  /**
+   * Create a {@link Timestamp}.
+   * 
+   * @param elapsedMillis
+   *          the elapsed time in milliseconds since the start of the build (null if unknown)
+   * @param millisSinceEpoch
+   *          the clock time in milliseconds since midnight, January 1, 1970 UTC
+   */
+  public Timestamp(Long elapsedMillis, long millisSinceEpoch) {
+    this.elapsedMillis = (elapsedMillis == null ? 0 : elapsedMillis);
+    this.elapsedMillisKnown = (elapsedMillis != null);
     this.millisSinceEpoch = millisSinceEpoch;
   }
 
@@ -63,7 +81,8 @@ public Timestamp(long elapsedMillis, long millisSinceEpoch) {
    */
   @Override
   public int hashCode() {
-    return Objects.hashCode(elapsedMillis, millisSinceEpoch);
+    return Objects
+        .hashCode(elapsedMillis, elapsedMillisKnown, millisSinceEpoch);
   }
 
   /**
@@ -74,6 +93,7 @@ public boolean equals(Object obj) {
     if (obj instanceof Timestamp) {
       Timestamp other = (Timestamp) obj;
       return elapsedMillis == other.elapsedMillis
+          && elapsedMillisKnown == other.elapsedMillisKnown
           && millisSinceEpoch == other.millisSinceEpoch;
     }
     return false;
@@ -84,7 +104,8 @@ public boolean equals(Object obj) {
    */
   @Override
   public String toString() {
-    return Objects.toStringHelper(this).add("elapsedMillis", elapsedMillis)
+    return Objects.toStringHelper(this)
+        .add("elapsedMillis", elapsedMillisKnown ? elapsedMillis : "(unknown)")
         .add("millisSinceEpoch", millisSinceEpoch).toString();
   }
 }
diff --git a/src/main/java/hudson/plugins/timestamper/TimestampNote.java b/src/main/java/hudson/plugins/timestamper/TimestampNote.java
@@ -63,6 +63,13 @@ public static String getSystemProperty() {
     return "timestamper-consolenotes";
   }
 
+  /**
+   * The elapsed time in milliseconds since the start of the build.
+   * 
+   * @since 1.7.4
+   */
+  private final Long elapsedMillis;
+
   /**
    * Milliseconds since the epoch.
    */
@@ -71,10 +78,13 @@ public static String getSystemProperty() {
   /**
    * Create a new {@link TimestampNote}.
    * 
+   * @param elapsedMillis
+   *          the elapsed time in milliseconds since the start of the build
    * @param millisSinceEpoch
    *          milliseconds since the epoch
    */
-  public TimestampNote(long millisSinceEpoch) {
+  public TimestampNote(long elapsedMillis, long millisSinceEpoch) {
+    this.elapsedMillis = elapsedMillis;
     this.millisSinceEpoch = millisSinceEpoch;
   }
 
@@ -86,8 +96,7 @@ public TimestampNote(long millisSinceEpoch) {
    * @return the time-stamp
    */
   public Timestamp getTimestamp(Run<?, ?> build) {
-    long elapsedMillis = millisSinceEpoch - build.getTimeInMillis();
-    return new Timestamp(elapsedMillis, millisSinceEpoch);
+    return getTimestamp((Object) build);
   }
 
   /**
@@ -96,12 +105,20 @@ public Timestamp getTimestamp(Run<?, ?> build) {
   @Override
   public ConsoleAnnotator<Object> annotate(Object context, MarkupText text,
       int charPos) {
+    TimestampFormatter formatter = TimestampFormatter.get();
+    Timestamp timestamp = getTimestamp(context);
+    formatter.markup(text, timestamp);
+    return null; // each time-stamp note affects one line only
+  }
+
+  private Timestamp getTimestamp(Object context) {
     if (context instanceof Run<?, ?>) {
+      // The elapsed time can be determined by using the build start time
       Run<?, ?> build = (Run<?, ?>) context;
-      TimestampFormatter formatter = TimestampFormatter.get();
-      Timestamp timestamp = getTimestamp(build);
-      formatter.markup(text, timestamp);
+      long buildStartTime = build.getTimeInMillis();
+      return new Timestamp(millisSinceEpoch - buildStartTime, millisSinceEpoch);
     }
-    return null; // each time-stamp note affects one line only
+    // Use the elapsed time recorded in this console note, if known
+    return new Timestamp(elapsedMillis, millisSinceEpoch);
   }
 }
diff --git a/src/main/java/hudson/plugins/timestamper/TimestampNotesOutputStream.java b/src/main/java/hudson/plugins/timestamper/TimestampNotesOutputStream.java
@@ -42,22 +42,31 @@ class TimestampNotesOutputStream extends LineTransformationOutputStream {
    */
   private final OutputStream delegate;
 
+  /**
+   * The build start time.
+   */
+  private final long buildStartTime;
+
   /**
    * Create a new {@link TimestampNotesOutputStream}.
    * 
    * @param delegate
    *          the delegate output stream
+   * @param buildStartTime
+   *          the build start time
    */
-  TimestampNotesOutputStream(OutputStream delegate) {
+  TimestampNotesOutputStream(OutputStream delegate, long buildStartTime) {
     this.delegate = checkNotNull(delegate);
+    this.buildStartTime = buildStartTime;
   }
 
   /**
    * {@inheritDoc}
    */
   @Override
   protected void eol(byte[] b, int len) throws IOException {
-    new TimestampNote(System.currentTimeMillis()).encodeTo(delegate);
+    long now = System.currentTimeMillis();
+    new TimestampNote(now - buildStartTime, now).encodeTo(delegate);
     delegate.write(b, 0, len);
   }
 

diff --git a/src/main/java/hudson/plugins/timestamper/TimestamperBuildWrapper.java b/src/main/java/hudson/plugins/timestamper/TimestamperBuildWrapper.java
@@ -103,7 +103,7 @@ private static class ConsoleLogFilterImpl extends ConsoleLogFilter implements Se
     @Override
     public OutputStream decorateLogger(AbstractBuild _ignore, OutputStream logger) throws IOException, InterruptedException {
       if (useTimestampNotes) {
-        return new TimestampNotesOutputStream(logger);
+        return new TimestampNotesOutputStream(logger, buildStartTime);
       }
       Optional<MessageDigest> digest = Optional.absent();
       try {

diff --git a/src/main/java/hudson/plugins/timestamper/format/TimestampFormatter.java b/src/main/java/hudson/plugins/timestamper/format/TimestampFormatter.java
@@ -205,8 +205,11 @@ private static class ElapsedTimeFormatFunction implements
 
     @Override
     public String apply(@Nonnull Timestamp timestamp) {
-      return DurationFormatUtils.formatDuration(timestamp.elapsedMillis,
-          elapsedTimeFormat);
+      if (timestamp.elapsedMillisKnown) {
+        return DurationFormatUtils.formatDuration(timestamp.elapsedMillis,
+            elapsedTimeFormat);
+      }
+      return "";
     }
   }
 

diff --git a/src/test/java/hudson/plugins/timestamper/TimestampNoteTest.java b/src/test/java/hudson/plugins/timestamper/TimestampNoteTest.java
@@ -25,9 +25,7 @@
 
 import static org.hamcrest.Matchers.is;
 import static org.junit.Assert.assertThat;
-import static org.mockito.Matchers.any;
 import static org.mockito.Mockito.mock;
-import static org.mockito.Mockito.never;
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.when;
 import hudson.MarkupText;
@@ -63,15 +61,21 @@ public class TimestampNoteTest {
 
   private MarkupText text;
 
+  private final long BUILD_START = 1;
+
+  private final long NOTE_ELAPSED = 4;
+
+  private final long TIME = 3;
+
   /**
    * @throws Exception
    */
   @Before
   public void setUp() throws Exception {
     build = PowerMockito.mock(Run.class);
-    when(build.getTimeInMillis()).thenReturn(1l);
+    when(build.getTimeInMillis()).thenReturn(BUILD_START);
 
-    note = new TimestampNote(3);
+    note = new TimestampNote(NOTE_ELAPSED, TIME);
 
     formatter = mock(TimestampFormatter.class);
     Whitebox.setInternalState(TimestampFormatter.class,
@@ -89,13 +93,14 @@ public TimestampFormatter get() {
    */
   @Test
   public void testGetTimestamp() {
-    assertThat(note.getTimestamp(build), is(new Timestamp(2, 3)));
+    assertThat(note.getTimestamp(build), is(new Timestamp(TIME
+        - BUILD_START, TIME)));
   }
 
   /**
    */
   @Test
-  public void testGetTimestampAfterSerialization() {
+  public void testGetTimestamp_afterSerialization() {
     note = (TimestampNote) SerializationUtils.clone(note);
     testGetTimestamp();
   }
@@ -105,23 +110,48 @@ public void testGetTimestampAfterSerialization() {
   @Test
   public void testAnnotate() {
     note.annotate(build, text, 0);
-    verify(formatter).markup(text, new Timestamp(2, 3));
+    verify(formatter).markup(text, new Timestamp(TIME - BUILD_START, TIME));
   }
 
   /**
    */
   @Test
-  public void testAnnotateAfterSerialization() {
+  public void testAnnotate_afterSerialization() {
     note = (TimestampNote) SerializationUtils.clone(note);
     testAnnotate();
   }
 
   /**
    */
   @Test
-  public void testAnnotateUnrecognisedContext() {
+  public void testAnnotate_unrecognisedContext() {
     note.annotate(new Object(), text, 0);
-    verify(formatter, never()).markup(any(MarkupText.class),
-        any(Timestamp.class));
+    verify(formatter)
+        .markup(text, new Timestamp(NOTE_ELAPSED, TIME));
+  }
+
+  /**
+   */
+  @Test
+  public void testAnnotate_UnrecognisedContext_afterSerialization() {
+    note = (TimestampNote) SerializationUtils.clone(note);
+    testAnnotate_unrecognisedContext();
+  }
+
+  /**
+   */
+  @Test
+  public void testAnnotate_unrecognisedContext_buildStartNotRecorded() {
+    Whitebox.setInternalState(note, "elapsedMillis", (Object)null);
+    note.annotate(new Object(), text, 0);
+    verify(formatter).markup(text, new Timestamp(null, TIME));
+  }
+
+  /**
+   */
+  @Test
+  public void testAnnotate_UnrecognisedContext_buildStartNotRecorded_afterSerialization() {
+    note = (TimestampNote) SerializationUtils.clone(note);
+    testAnnotate_unrecognisedContext_buildStartNotRecorded();
   }
 }
diff --git a/src/test/java/hudson/plugins/timestamper/TimestampNotesOutputStreamTest.java b/src/test/java/hudson/plugins/timestamper/TimestampNotesOutputStreamTest.java
@@ -58,7 +58,7 @@ public class TimestampNotesOutputStreamTest {
   public void setUp() {
     delegateOutputStream = new ByteArrayOutputStream();
     timestampNotesOutputStream = new TimestampNotesOutputStream(
-        delegateOutputStream);
+        delegateOutputStream, 0);
   }
 
   /**

diff --git a/src/test/java/hudson/plugins/timestamper/TimestampTest.java b/src/test/java/hudson/plugins/timestamper/TimestampTest.java
@@ -44,11 +44,23 @@ public class TimestampTest {
   /**
    */
   @Test
+  @SuppressWarnings("unchecked")
   public void testConstructor() {
     Timestamp timestamp = new Timestamp(123, 42000);
-    assertThat(
-        Arrays.asList(timestamp.elapsedMillis, timestamp.millisSinceEpoch),
-        is(Arrays.asList(123l, 42000l)));
+    assertThat(Arrays.asList(timestamp.elapsedMillis,
+        timestamp.elapsedMillisKnown, timestamp.millisSinceEpoch),
+        is(Arrays.asList(123l, true, 42000l)));
+  }
+
+  /**
+   */
+  @Test
+  @SuppressWarnings("unchecked")
+  public void testConstructor_unknownElapsed() {
+    Timestamp timestamp = new Timestamp(null, 42000);
+    assertThat(Arrays.asList(timestamp.elapsedMillis,
+        timestamp.elapsedMillisKnown, timestamp.millisSinceEpoch),
+        is(Arrays.asList(0l, false, 42000l)));
   }
 
   /**

diff --git a/src/test/java/hudson/plugins/timestamper/action/TimestampsActionTest.java b/src/test/java/hudson/plugins/timestamper/action/TimestampsActionTest.java
@@ -306,7 +306,7 @@ public void writeTimestamps() throws Exception {
       ByteArrayOutputStream outputStream = new ByteArrayOutputStream();
       int i = 0;
       for (long millisSinceEpoch : millisSinceEpochToWrite) {
-        TimestampNote timestampNote = new TimestampNote(millisSinceEpoch);
+        TimestampNote timestampNote = new TimestampNote(0, millisSinceEpoch);
         timestampNote.encodeTo(outputStream);
         outputStream.write('a' + i);
         i++;