feat: Allow configuring run summary logging behavior

Motivation:

Logging every 5 seconds is very verbose for long tests.

Modifications:

- Allow disabling run summary logging entirely.
- Allow configuring the run summary refresh interval, with the ability to switch to a longer interval after a certain time.

Result:

Less verbose logs (both by default or depending on configuration).

action.yml

@@ -31,6 +31,22 @@ inputs:
     description: 'Whether the action should wait for the end of the Gatling Enterprise simulation run before terminating. True by default. If set to false, some of this action''s outputs may be missing.'
     required: false
     default: 'true'
+  run_summary_enabled:
+    description: 'Assuming wait_for_run_end is also true, will regularly log a summary of the ongoing run to the console until it finishes. True by default.'
+    required: false
+    default: 'true'
+  run_summary_initial_refresh_interval:
+    description: 'Initial interval before displaying a new summary of the ongoing run in the console, in seconds. 5 seconds by default. Should be a multiple of 5 (otherwise it will be rounded up). Only used a limited number of times (set by run_summary_initial_refresh_count) before switching to the interval set by run_summary_permanent_refresh_interval.'
+    required: false
+    default: '5'
+  run_summary_initial_refresh_count:
+    description: 'Number of times to use run_summary_initial_refresh_interval as the interval before displaying a new summary of the ongoing run in the console. 12 times by default (i.e. 60 seconds with the default run_summary_initial_refresh_interval of 5 seconds). After that, run_summary_permanent_refresh_interval will be used. This allows to avoid spamming the log output once the test run is well underway.'
+    required: false
+    default: '12'
+  run_summary_refresh_interval:
+    description: 'Interval before displaying a new summary of the ongoing run in the console, in seconds. 60 seconds by default. Should be a multiple of 5 (otherwise it will be rounded up).'
+    required: false
+    default: '60'
 outputs:
   run_id:
     description: 'ID of the run started by this action.'

common/src/config.ts

@@ -7,6 +7,7 @@ export interface Config {
   run: RunConfig;
   failActionOnRunFailure: boolean;
   waitForRunEnd: boolean;
+  runSummaryLoggingConfiguration: RunSummaryLoggingConfiguration;
 }
 
 export interface RunConfig {
@@ -21,6 +22,13 @@ export interface LoadGeneratorConfiguration {
   weight?: number;
 }
 
+export interface RunSummaryLoggingConfiguration {
+  enabled: boolean;
+  initialRefreshInterval: number;
+  initialRefreshCount: number;
+  refreshInterval: number;
+}
+
 export const requiredInputValidation = string.filter((str) => str !== "");
 export const optionalInputValidation = string.map((str) => (str === "" ? undefined : str));
 export const requiredBooleanValidation = requiredInputValidation.and((str) => {
@@ -56,3 +64,22 @@ const overrideLoadGeneratorsValidation = jsonValidation.then(
 export const overrideLoadGeneratorsInputValidation = optionalInputValidation.then(
   overrideLoadGeneratorsValidation.optional()
 );
+
+export const parseStrictlyPositiveNumberValidation = (roundingUpMultiple: number) =>
+  requiredInputValidation.and((str) => {
+    const parsedValue = parseFloat(str);
+    if (isNaN(parsedValue)) {
+      return Err(`Invalid integer value: ${str}`);
+    } else if (parsedValue <= 0) {
+      return Err(`Should be strictly positive`);
+    } else {
+      return Ok(
+        roundingUpMultiple !== undefined
+          ? Math.ceil(parsedValue / roundingUpMultiple) * roundingUpMultiple
+          : parsedValue
+      );
+    }
+  });
+
+export const runSummaryInitialRefreshCountValidation = parseStrictlyPositiveNumberValidation(1);
+export const runSummaryRefreshIntervalValidation = parseStrictlyPositiveNumberValidation(5);

common/src/run/metrics.ts

@@ -4,11 +4,17 @@ import { ApiClient } from "../client/apiClient";
 import { RequestsSummaryChild } from "../client/responses/requestsSummaryResponse";
 import { RunInformationResponse } from "../client/responses/runInformationResponse";
 import { Logger } from "../log";
-import { formatDuration } from "../utils";
+import { formatDuration, formatDurationDiff } from "../utils";
 
-export const getAndLogMetricsSummary = async (client: ApiClient, logger: Logger, runInfo: RunInformationResponse) => {
+export const getAndLogMetricsSummary = async (
+  client: ApiClient,
+  logger: Logger,
+  runInfo: RunInformationResponse,
+  elapsedTimeMillis: number,
+  nextSummaryDelayMillis: number
+) => {
   const metricsSummary = await getMetricsSummary(client, runInfo);
-  logMetricsSummary(logger, metricsSummary);
+  logMetricsSummary(logger, metricsSummary, elapsedTimeMillis, nextSummaryDelayMillis);
 };
 
 const getMetricsSummary = async (client: ApiClient, runInfo: RunInformationResponse): Promise<MetricsSummary> => {
@@ -19,7 +25,7 @@ const getMetricsSummary = async (client: ApiClient, runInfo: RunInformationRespo
 
   const currentTimestamp = Date.now();
   const date = format(currentTimestamp, "yyyy-MM-dd HH:mm:ss");
-  const duration = formatDuration(runInfo.injectStart, currentTimestamp);
+  const duration = formatDurationDiff(runInfo.injectStart, currentTimestamp);
 
   const nbUsers = seriesResponse
     .map(({ values }) => (values.length === 0 ? 0.0 : values[values.length - 1]))
@@ -53,9 +59,11 @@ const recursivelyGetChildren = (children: RequestsSummaryChild[]): ChildMetric[]
         }
   );
 
-const logMetricsSummary = (logger: Logger, summary: MetricsSummary) => {
+const logMetricsSummary = (logger: Logger, summary: MetricsSummary, elapsedTime: number, nextSummaryDelay: number) => {
   logger.group(
-    `Time: ${summary.date}, ${summary.duration} elapsed`,
+    `Time: ${summary.date}, ${formatDuration(elapsedTime)} elapsed, next refresh in ${formatDuration(
+      nextSummaryDelay
+    )}`,
     (summary.nbUsers > 0 ? `Number of concurrent users: ${summary.nbUsers}\n` : "") +
       `Number of requests: ${summary.nbRequest}\n` +
       `Number of requests per seconds: ${summary.requestsSeconds}\n` +

common/src/run/ongoing.ts

@@ -1,4 +1,4 @@
-import { setTimeout } from "timers/promises";
+import { setInterval } from "timers/promises";
 
 import { ApiClient } from "../client/apiClient";
 import { Assertion, RunInformationResponse } from "../client/responses/runInformationResponse";
@@ -7,6 +7,7 @@ import { getAndLogMetricsSummary } from "../run/metrics";
 import { StartedRun } from "../run/start";
 import { isRunning, statusName } from "../run/status";
 import { formatErrorMessage, console } from "../utils";
+import { Config } from "../config";
 
 export interface FinishedRun {
   runId: String;
@@ -16,44 +17,96 @@ export interface FinishedRun {
 }
 
 const MAX_CONSECUTIVE_ERRORS = 5;
+const REFRESH_DELAY_MILLIS = 5000;
 
 export const waitForRunEnd = async (
   client: ApiClient,
+  config: Config,
+  logger: Logger,
+  startedRun: StartedRun
+): Promise<FinishedRun> => {
+  const cancelInterval = new AbortController();
+  const intervalIterator = setInterval(REFRESH_DELAY_MILLIS, undefined, { signal: cancelInterval.signal })[
+    Symbol.asyncIterator
+  ]();
+  try {
+    return await waitForRunEndLoop(intervalIterator, client, config, logger, startedRun);
+  } finally {
+    cancelInterval.abort();
+  }
+};
+
+const waitForRunEndLoop = async (
+  intervalIterator: AsyncIterator<unknown>,
+  client: ApiClient,
+  config: Config,
   logger: Logger,
   startedRun: StartedRun
 ): Promise<FinishedRun> => {
   let runInfo: RunInformationResponse | undefined;
   let oldStatus: number = -1;
   let consecutiveErrorsCount = 0;
+
+  const summaryEnabled = config.runSummaryLoggingConfiguration.enabled;
+  const initialIntervalMillis = config.runSummaryLoggingConfiguration.initialRefreshInterval * 1000;
+  const initialIntervalCount = config.runSummaryLoggingConfiguration.initialRefreshCount;
+  const intervalMillis = config.runSummaryLoggingConfiguration.refreshInterval * 1000;
+
+  let refreshIntervalMillis = initialIntervalMillis;
+  let lastSummaryDisplayMillis = -1;
+  let iterationsSinceRunStart = 0;
+  let currentSummaryNo = 0;
+
   do {
     try {
-      await setTimeout(5000); // Initial delay even on first iteration because run duration might not be populated yet
+      await intervalIterator.next(); // Initial delay even on first iteration because run duration might not be populated yet
+
       runInfo = await client.getRunInformation(startedRun.runId);
       const statusMsg = `Run status is now ${statusName(runInfo.status)} [${runInfo.status}]`;
       runInfo.status !== oldStatus ? logger.log(statusMsg) : logger.debug(statusMsg);
       oldStatus = runInfo.status;
-      if (runInfo.injectStart > 0) {
-        await getAndLogMetricsSummary(client, logger, runInfo);
+
+      if (summaryEnabled && runInfo.injectStart > 0) {
+        iterationsSinceRunStart++;
+        const elapsedTimeMillis = iterationsSinceRunStart * REFRESH_DELAY_MILLIS;
+        logger.debug(`elapsedTimeMillis=${elapsedTimeMillis}`);
+        logger.debug(`lastSummaryDisplayMillis=${lastSummaryDisplayMillis}`);
+        logger.debug(`refreshIntervalMillis=${refreshIntervalMillis}`);
+        if (elapsedTimeMillis - lastSummaryDisplayMillis >= refreshIntervalMillis) {
+          currentSummaryNo++;
+          if (currentSummaryNo >= initialIntervalCount) {
+            refreshIntervalMillis = intervalMillis;
+          }
+          const displayedRefreshInterval =
+            Math.ceil(refreshIntervalMillis / REFRESH_DELAY_MILLIS) * REFRESH_DELAY_MILLIS; // Round up to nearest 5 seconds as it's our max resolution
+          await getAndLogMetricsSummary(client, logger, runInfo, elapsedTimeMillis, displayedRefreshInterval);
+          lastSummaryDisplayMillis = elapsedTimeMillis;
+        }
       }
       consecutiveErrorsCount = 0;
     } catch (error) {
       consecutiveErrorsCount++;
-      if (consecutiveErrorsCount < MAX_CONSECUTIVE_ERRORS) {
-        const msg = formatErrorMessage(error);
-        logger.log(
-          console.yellow(
-            `Failed to retrieve current run information (attempt ${consecutiveErrorsCount}/${MAX_CONSECUTIVE_ERRORS}): ${msg}`
-          )
-        );
-      } else {
-        throw error;
-      }
+      handleError(logger, error, consecutiveErrorsCount);
     }
   } while (runInfo === undefined || isRunning(runInfo.status));
+
   return {
     runId: runInfo.runId,
     statusCode: runInfo.status,
     statusName: statusName(runInfo.status),
     assertions: runInfo.assertions
   };
 };
+
+const handleError = (logger: Logger, error: any, errorCount: number) => {
+  if (errorCount < MAX_CONSECUTIVE_ERRORS) {
+    const msg = formatErrorMessage(error);
+    logger.log(
+      console.yellow(
+        `Failed to retrieve current run information (attempt ${errorCount}/${MAX_CONSECUTIVE_ERRORS}): ${msg}`
+      )
+    );
+  } else {
+    throw error;
+  }
+};

common/src/runMain.ts

@@ -29,7 +29,7 @@ export const runMain = async (output: Output, logger: Logger, config: Config, st
     await output.set("runs_url", startedRun.runsUrl);
 
     if (config.waitForRunEnd) {
-      const finishedRun = await waitForRunEnd(client, logger, startedRun);
+      const finishedRun = await waitForRunEnd(client, config, logger, startedRun);
       state.setFinished(); // Run finished, no cleanup needed
       logAssertionResults(logger, finishedRun.assertions);
       logResult(logger, config, startedRun, finishedRun);

common/src/utils/duration.ts

@@ -5,9 +5,15 @@ import assert from "assert";
  * @param start timestamp in milliseconds
  * @param end timestamp in milliseconds
  */
-export const formatDuration = (start: number, end: number): string => {
-  const totalSeconds = Math.floor((end - start) / 1000);
-  assert(totalSeconds >= 0, "Cannot format negative duration");
+export const formatDurationDiff = (start: number, end: number): string => formatDuration(end - start);
+
+/**
+ * Formats duration with a format like "2h 25m 12s".
+ * @param duration duration in milliseconds
+ */
+export const formatDuration = (duration: number): string => {
+  assert(duration >= 0, "Cannot format negative duration");
+  const totalSeconds = Math.floor(duration / 1000);
 
   let formattedStr = "";
   let remainder = totalSeconds;

common/src/utils/index.ts

@@ -1,4 +1,4 @@
 export { formatErrorMessage } from "./error";
-export { formatDuration } from "./duration";
+export { formatDuration, formatDurationDiff } from "./duration";
 
 export * as console from "./console";

common/test/config.test.ts

@@ -3,7 +3,8 @@ import {
   configKeysInputValidation,
   overrideLoadGeneratorsInputValidation,
   requiredBooleanValidation,
-  uuidValidation
+  uuidValidation,
+  parseStrictlyPositiveNumberValidation
 } from "@src/config";
 
 test("requiredBooleanValidation", () => {
@@ -82,3 +83,25 @@ test("hostsByPoolInputValidation", () => {
   );
   expect(overrideLoadGeneratorsInputValidation.validate('"bcf62ac8-90a0-4be7-acd0-d7e87e3cbd66"').ok).toBe(false);
 });
+
+test("parseNumberValidation", () => {
+  const exactRes = parseStrictlyPositiveNumberValidation(5).validate("5");
+  expect(exactRes.ok && exactRes.value).toStrictEqual(5);
+
+  const floatRoundUpRes1 = parseStrictlyPositiveNumberValidation(5).validate("3.9");
+  expect(floatRoundUpRes1.ok && floatRoundUpRes1.value).toStrictEqual(5);
+
+  const floatRoundUpRes2 = parseStrictlyPositiveNumberValidation(1).validate("3.9");
+  expect(floatRoundUpRes2.ok && floatRoundUpRes2.value).toStrictEqual(4);
+
+  const integerRoundUpRes = parseStrictlyPositiveNumberValidation(5).validate("42");
+  expect(integerRoundUpRes.ok && integerRoundUpRes.value).toStrictEqual(45);
+
+  const expRes = parseStrictlyPositiveNumberValidation(5).validate("1.23e5");
+  expect(expRes.ok && expRes.value).toStrictEqual(123000);
+
+  expect(parseStrictlyPositiveNumberValidation(5).validate("").ok).toBe(false);
+  expect(parseStrictlyPositiveNumberValidation(5).validate("foo").ok).toBe(false);
+  expect(parseStrictlyPositiveNumberValidation(5).validate("0").ok).toBe(false);
+  expect(parseStrictlyPositiveNumberValidation(5).validate("-5.1").ok).toBe(false);
+});

common/test/utils/duration.test.ts

@@ -1,56 +1,56 @@
 import { expect, test } from "@jest/globals";
-import { formatDuration } from "@src/utils/duration";
+import { formatDurationDiff } from "@src/utils/duration";
 
 test("formatDuration d/h/m/s", () => {
   const start = new Date(2022, 12, 14, 7, 52, 15, 0).getTime();
   const end = new Date(2022, 12, 16, 10, 13, 52, 12).getTime();
-  expect(formatDuration(start, end)).toBe("2d 2h 21m 37s");
+  expect(formatDurationDiff(start, end)).toBe("2d 2h 21m 37s");
 });
 
 test("formatDuration d/h/m/s with exact day", () => {
   const start = new Date(2022, 12, 14, 7, 52, 15, 24).getTime();
   const end = new Date(2022, 12, 16, 7, 52, 15, 29).getTime();
-  expect(formatDuration(start, end)).toBe("2d 0h 0m 0s");
+  expect(formatDurationDiff(start, end)).toBe("2d 0h 0m 0s");
 });
 
 test("formatDuration h/m/s", () => {
   const start = new Date(2022, 12, 14, 7, 52, 15, 0).getTime();
   const end = new Date(2022, 12, 15, 7, 13, 52, 12).getTime();
-  expect(formatDuration(start, end)).toBe("23h 21m 37s");
+  expect(formatDurationDiff(start, end)).toBe("23h 21m 37s");
 });
 
 test("formatDuration h/m/s with exact hour", () => {
   const start = new Date(2022, 12, 14, 7, 52, 15, 0).getTime();
   const end = new Date(2022, 12, 15, 5, 52, 15, 12).getTime();
-  expect(formatDuration(start, end)).toBe("22h 0m 0s");
+  expect(formatDurationDiff(start, end)).toBe("22h 0m 0s");
 });
 
 test("formatDuration m/s", () => {
   const start = new Date(2022, 12, 14, 7, 13, 52, 12).getTime();
   const end = new Date(2022, 12, 14, 7, 52, 15, 0).getTime();
-  expect(formatDuration(start, end)).toBe("38m 22s");
+  expect(formatDurationDiff(start, end)).toBe("38m 22s");
 });
 
 test("formatDuration m/s with exact minute", () => {
   const start = new Date(2022, 12, 14, 7, 13, 25, 58).getTime();
   const end = new Date(2022, 12, 14, 7, 51, 26, 5).getTime();
-  expect(formatDuration(start, end)).toBe("38m 0s");
+  expect(formatDurationDiff(start, end)).toBe("38m 0s");
 });
 
 test("formatDuration s", () => {
   const start = new Date(2022, 12, 14, 7, 51, 52, 12).getTime();
   const end = new Date(2022, 12, 14, 7, 52, 15, 0).getTime();
-  expect(formatDuration(start, end)).toBe("22s");
+  expect(formatDurationDiff(start, end)).toBe("22s");
 });
 
 test("formatDuration zero duration", () => {
   const start = new Date(2022, 12, 14, 7, 52, 15, 0).getTime();
   const end = new Date(2022, 12, 14, 7, 52, 15, 0).getTime();
-  expect(formatDuration(start, end)).toBe("0s");
+  expect(formatDurationDiff(start, end)).toBe("0s");
 });
 
 test("formatDuration negative duration", () => {
   const start = new Date(2022, 12, 14, 7, 52, 15, 0).getTime();
   const end = new Date(2022, 12, 14, 7, 52, 14, 0).getTime();
-  expect(() => formatDuration(start, end)).toThrow();
+  expect(() => formatDurationDiff(start, end)).toThrow();
 });