Compute timestamp Using Date.now (without deriving from duration) (#1431

)

This fixes a few bugs with time/duration handling:

* The timestamp of testRunStarted was 0. It's been fixed to be an actual timestamp (Date.now).
* The timestamp of testRunFinshed was not a timestamp, but a duration camouflaged as a timestamp.
* The stopwatch.timestamp() method no longer calculates the timestamp from a duration (which is impossible). Instead it uses Date.now()
* Previously the reports test run duration was based on the testRunFinished timestamp alone, which didn't make sense. A timestamp is not a duration. Instead we calculate it using the difference of the testRunStarted and testRunFinished timestamps

We think there is still some work to do to clean up the timestamp/duration code, but this should be done in a separate PR. This PR simply focuses on getting correct values into the messages.

Co-authored-by: Aslak Hellesøy <[email protected]>

src/formatter/helpers/summary_helpers.ts

@@ -1,14 +1,10 @@
 import _ from 'lodash'
 import Duration from 'duration'
 import Status from '../../status'
-import {
-  addDurations,
-  durationToMilliseconds,
-  getZeroDuration,
-} from '../../time'
+import { addDurations, getZeroDuration } from '../../time'
 import { IColorFns } from '../get_color_fns'
 import { ITestCaseAttempt } from './event_data_collector'
-import { messages } from '@cucumber/messages'
+import { messages, TimeConversion } from '@cucumber/messages'
 
 const STATUS_REPORT_ORDER = [
   Status.FAILED,
@@ -22,13 +18,13 @@ const STATUS_REPORT_ORDER = [
 export interface IFormatSummaryRequest {
   colorFns: IColorFns
   testCaseAttempts: ITestCaseAttempt[]
-  testRunFinished: messages.ITestRunFinished
+  testRunDuration: messages.IDuration
 }
 
 export function formatSummary({
   colorFns,
   testCaseAttempts,
-  testRunFinished,
+  testRunDuration,
 }: IFormatSummaryRequest): string {
   const testCaseResults: messages.TestStepFinished.ITestStepResult[] = []
   const testStepResults: messages.TestStepFinished.ITestStepResult[] = []
@@ -57,7 +53,7 @@ export function formatSummary({
     type: 'step',
   })
   const durationSummary = `${getDurationSummary(
-    testRunFinished.timestamp
+    testRunDuration
   )} (executing steps: ${getDurationSummary(totalStepDuration)})\n`
   return [scenarioSummary, stepSummary, durationSummary].join('\n')
 }
@@ -92,11 +88,9 @@ function getCountSummary({
   return text
 }
 
-function getDurationSummary(
-  durationMsg: messages.IDuration | messages.ITimestamp
-): string {
+function getDurationSummary(durationMsg: messages.IDuration): string {
   const start = new Date(0)
-  const end = new Date(durationToMilliseconds(durationMsg))
+  const end = new Date(TimeConversion.durationToMilliseconds(durationMsg))
   const duration = new Duration(start, end)
   // Use spaces in toString method for readability and to avoid %Ls which is a format
   return duration.toString('%Ms m %S . %L s').replace(/ /g, '')

src/formatter/helpers/summary_helpers_spec.ts

@@ -5,7 +5,7 @@ import { formatSummary } from './summary_helpers'
 import { getTestCaseAttempts } from '../../../test/formatter_helpers'
 import { getBaseSupportCodeLibrary } from '../../../test/fixtures/steps'
 import FakeTimers, { InstalledClock } from '@sinonjs/fake-timers'
-import timeMethods from '../../time'
+import timeMethods, { durationBetweenTimestamps } from '../../time'
 import { buildSupportCodeLibrary } from '../../../test/runtime_helpers'
 import { IRuntimeOptions } from '../../runtime'
 import { ISupportCodeLibrary } from '../../support_code_library_builder/types'
@@ -16,13 +16,15 @@ interface ITestFormatSummaryOptions {
   runtimeOptions?: Partial<IRuntimeOptions>
   sourceData: string
   supportCodeLibrary?: ISupportCodeLibrary
+  testRunStarted?: messages.ITestRunStarted
   testRunFinished?: messages.ITestRunFinished
 }
 
 async function testFormatSummary({
   runtimeOptions,
   sourceData,
   supportCodeLibrary,
+  testRunStarted,
   testRunFinished,
 }: ITestFormatSummaryOptions): Promise<string> {
   const sources = [
@@ -34,6 +36,14 @@ async function testFormatSummary({
   if (doesNotHaveValue(supportCodeLibrary)) {
     supportCodeLibrary = getBaseSupportCodeLibrary()
   }
+  if (doesNotHaveValue(testRunStarted)) {
+    testRunStarted = messages.TestRunStarted.fromObject({
+      timestamp: {
+        nanos: 0,
+        seconds: 0,
+      },
+    })
+  }
   if (doesNotHaveValue(testRunFinished)) {
     testRunFinished = messages.TestRunFinished.fromObject({
       timestamp: {
@@ -50,7 +60,10 @@ async function testFormatSummary({
   return formatSummary({
     colorFns: getColorFns(false),
     testCaseAttempts,
-    testRunFinished,
+    testRunDuration: durationBetweenTimestamps(
+      testRunStarted.timestamp,
+      testRunFinished.timestamp
+    ),
   })
 }
 
@@ -242,10 +255,16 @@ describe('SummaryHelpers', () => {
         const output = await testFormatSummary({
           sourceData,
           supportCodeLibrary,
+          testRunStarted: messages.TestRunStarted.fromObject({
+            timestamp: {
+              nanos: 0,
+              seconds: 3,
+            },
+          }),
           testRunFinished: messages.TestRunFinished.fromObject({
             timestamp: {
               nanos: 124000000,
-              seconds: 0,
+              seconds: 3,
             },
           }),
         })

src/formatter/progress_bar_formatter.ts

@@ -5,10 +5,12 @@ import { WriteStream as TtyWriteStream } from 'tty'
 import { messages } from '@cucumber/messages'
 import { doesHaveValue, valueOrDefault } from '../value_checker'
 import { formatUndefinedParameterType } from './helpers/issue_helpers'
+import { durationBetweenTimestamps } from '../time'
 
 // Inspired by https://github.com/thekompanee/fuubar and https://github.com/martinciu/fuubar-cucumber
 export default class ProgressBarFormatter extends Formatter {
   private numberOfSteps: number
+  private testRunStarted: messages.ITestRunStarted
   private issueCount: number
   public progressBar: ProgressBar
 
@@ -87,11 +89,15 @@ export default class ProgressBarFormatter extends Formatter {
   }
 
   logSummary(testRunFinished: messages.ITestRunFinished): void {
+    const testRunDuration = durationBetweenTimestamps(
+      this.testRunStarted.timestamp,
+      testRunFinished.timestamp
+    )
     this.log(
       formatSummary({
         colorFns: this.colorFns,
         testCaseAttempts: this.eventDataCollector.getTestCaseAttempts(),
-        testRunFinished,
+        testRunDuration,
       })
     )
   }
@@ -107,6 +113,8 @@ export default class ProgressBarFormatter extends Formatter {
       this.logProgress(envelope.testStepFinished)
     } else if (doesHaveValue(envelope.testCaseFinished)) {
       this.logErrorIfNeeded(envelope.testCaseFinished)
+    } else if (doesHaveValue(envelope.testRunStarted)) {
+      this.testRunStarted = envelope.testRunStarted
     } else if (doesHaveValue(envelope.testRunFinished)) {
       this.logSummary(envelope.testRunFinished)
     }

src/formatter/summary_formatter.ts

@@ -5,6 +5,7 @@ import { doesHaveValue } from '../value_checker'
 import { messages } from '@cucumber/messages'
 import { ITestCaseAttempt } from './helpers/event_data_collector'
 import { formatUndefinedParameterTypes } from './helpers/issue_helpers'
+import { durationBetweenTimestamps } from '../time'
 
 interface ILogIssuesRequest {
   issues: ITestCaseAttempt[]
@@ -14,14 +15,24 @@ interface ILogIssuesRequest {
 export default class SummaryFormatter extends Formatter {
   constructor(options: IFormatterOptions) {
     super(options)
+    let testRunStartedTimestamp: messages.ITimestamp
     options.eventBroadcaster.on('envelope', (envelope: messages.IEnvelope) => {
+      if (doesHaveValue(envelope.testRunStarted)) {
+        testRunStartedTimestamp = envelope.testRunStarted.timestamp
+      }
       if (doesHaveValue(envelope.testRunFinished)) {
-        this.logSummary(envelope.testRunFinished)
+        const testRunFinishedTimestamp = envelope.testRunFinished.timestamp
+        this.logSummary(
+          durationBetweenTimestamps(
+            testRunStartedTimestamp,
+            testRunFinishedTimestamp
+          )
+        )
       }
     })
   }
 
-  logSummary(testRunFinished: messages.ITestRunFinished): void {
+  logSummary(testRunDuration: messages.IDuration): void {
     const failures: ITestCaseAttempt[] = []
     const warnings: ITestCaseAttempt[] = []
     const testCaseAttempts = this.eventDataCollector.getTestCaseAttempts()
@@ -49,7 +60,7 @@ export default class SummaryFormatter extends Formatter {
       formatSummary({
         colorFns: this.colorFns,
         testCaseAttempts,
-        testRunFinished,
+        testRunDuration,
       })
     )
   }

src/runtime/index.ts

@@ -129,10 +129,7 @@ export default class Runtime {
       'envelope',
       new messages.Envelope({
         testRunStarted: {
-          timestamp: {
-            nanos: 0,
-            seconds: 0,
-          },
+          timestamp: this.stopwatch.timestamp(),
         },
       })
     )

src/runtime/parallel/coordinator.ts

@@ -205,10 +205,7 @@ export default class Coordinator {
       'envelope',
       new messages.Envelope({
         testRunStarted: {
-          timestamp: {
-            nanos: 0,
-            seconds: 0,
-          },
+          timestamp: this.stopwatch.timestamp(),
         },
       })
     )

src/runtime/pickle_runner_spec.ts

@@ -125,28 +125,28 @@ describe('PickleRunner', () => {
               attempt: 0,
               id: '2',
               testCaseId: '0',
-              timestamp: predictableTimestamp(1),
+              timestamp: predictableTimestamp(0),
             },
           }),
           messages.Envelope.fromObject({
             testStepStarted: {
               testCaseStartedId: '2',
               testStepId: '1',
-              timestamp: predictableTimestamp(2),
+              timestamp: predictableTimestamp(1),
             },
           }),
           messages.Envelope.fromObject({
             testStepFinished: {
               testCaseStartedId: '2',
               testStepResult: passedTestResult,
               testStepId: '1',
-              timestamp: predictableTimestamp(3),
+              timestamp: predictableTimestamp(2),
             },
           }),
           messages.Envelope.fromObject({
             testCaseFinished: {
               testCaseStartedId: '2',
-              timestamp: predictableTimestamp(4),
+              timestamp: predictableTimestamp(3),
             },
           }),
         ])
@@ -401,14 +401,14 @@ describe('PickleRunner', () => {
               attempt: 0,
               id: '2',
               testCaseId: '0',
-              timestamp: predictableTimestamp(1),
+              timestamp: predictableTimestamp(0),
             },
           }),
           messages.Envelope.fromObject({
             testStepStarted: {
               testCaseStartedId: '2',
               testStepId: '1',
-              timestamp: predictableTimestamp(2),
+              timestamp: predictableTimestamp(1),
             },
           }),
           messages.Envelope.fromObject({
@@ -421,28 +421,28 @@ describe('PickleRunner', () => {
                 willBeRetried: true,
               },
               testStepId: '1',
-              timestamp: predictableTimestamp(3),
+              timestamp: predictableTimestamp(2),
             },
           }),
           messages.Envelope.fromObject({
             testCaseFinished: {
               testCaseStartedId: '2',
-              timestamp: predictableTimestamp(4),
+              timestamp: predictableTimestamp(3),
             },
           }),
           messages.Envelope.fromObject({
             testCaseStarted: {
               attempt: 1,
               id: '3',
               testCaseId: '0',
-              timestamp: predictableTimestamp(5),
+              timestamp: predictableTimestamp(4),
             },
           }),
           messages.Envelope.fromObject({
             testStepStarted: {
               testCaseStartedId: '3',
               testStepId: '1',
-              timestamp: predictableTimestamp(6),
+              timestamp: predictableTimestamp(5),
             },
           }),
           messages.Envelope.fromObject({
@@ -453,13 +453,13 @@ describe('PickleRunner', () => {
                 status: Status.PASSED,
               },
               testStepId: '1',
-              timestamp: predictableTimestamp(7),
+              timestamp: predictableTimestamp(6),
             },
           }),
           messages.Envelope.fromObject({
             testCaseFinished: {
               testCaseStartedId: '3',
-              timestamp: predictableTimestamp(8),
+              timestamp: predictableTimestamp(7),
             },
           }),
         ])

src/runtime/stopwatch.ts

@@ -1,4 +1,4 @@
-import { messages } from '@cucumber/messages'
+import { messages, TimeConversion } from '@cucumber/messages'
 import { stopwatch, Stopwatch, duration, Duration } from 'durations'
 
 export interface ITestRunStopwatch {
@@ -37,7 +37,7 @@ export class RealTestRunStopwatch implements ITestRunStopwatch {
   }
 
   timestamp(): messages.ITimestamp {
-    return convertToTimestamp(this.duration())
+    return TimeConversion.millisecondsSinceEpochToTimestamp(Date.now())
   }
 }
 
@@ -67,16 +67,18 @@ export class PredictableTestRunStopwatch implements ITestRunStopwatch {
   }
 
   timestamp(): messages.ITimestamp {
+    const fakeTimestamp = this.convertToTimestamp(this.duration())
     this.count++
-    return convertToTimestamp(this.duration())
+    return fakeTimestamp
   }
-}
 
-function convertToTimestamp(duration: Duration): messages.ITimestamp {
-  const seconds = Math.floor(duration.seconds())
-  const nanos = Math.floor((duration.seconds() - seconds) * 1000000000)
-  return {
-    seconds,
-    nanos,
+  // TODO: Remove. It's impossible to convert timestamps to durations and vice-versa
+  private convertToTimestamp(duration: Duration): messages.ITimestamp {
+    const seconds = Math.floor(duration.seconds())
+    const nanos = Math.floor((duration.seconds() - seconds) * 1000000000)
+    return {
+      seconds,
+      nanos,
+    }
   }
 }