From 2fafd13de27708f70265fbb703b493df46b508b5 Mon Sep 17 00:00:00 2001 From: Guillaume Galy Date: Mon, 18 Sep 2023 10:15:26 +0200 Subject: [PATCH] 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 | 16 ++++++ common/src/config.ts | 27 ++++++++++ common/src/run/metrics.ts | 20 +++++--- common/src/run/ongoing.ts | 81 ++++++++++++++++++++++++------ common/src/runMain.ts | 2 +- common/src/utils/duration.ts | 12 +++-- common/src/utils/index.ts | 2 +- common/test/config.test.ts | 25 ++++++++- common/test/utils/duration.test.ts | 20 ++++---- docker/src/config.ts | 32 ++++++++++-- gh-action/src/config.ts | 27 ++++++++-- 11 files changed, 221 insertions(+), 43 deletions(-) diff --git a/action.yml b/action.yml index c16b6f8..047072a 100644 --- a/action.yml +++ b/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.' diff --git a/common/src/config.ts b/common/src/config.ts index 328bbf4..223f640 100644 --- a/common/src/config.ts +++ b/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); diff --git a/common/src/run/metrics.ts b/common/src/run/metrics.ts index 9f50aaf..f7b60db 100644 --- a/common/src/run/metrics.ts +++ b/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 => { @@ -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` + diff --git a/common/src/run/ongoing.ts b/common/src/run/ongoing.ts index cb00b64..32b5d41 100644 --- a/common/src/run/ongoing.ts +++ b/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,40 +17,79 @@ 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 => { + 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, + client: ApiClient, + config: Config, logger: Logger, startedRun: StartedRun ): Promise => { 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, @@ -57,3 +97,16 @@ export const waitForRunEnd = async ( 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; + } +}; diff --git a/common/src/runMain.ts b/common/src/runMain.ts index d68d1a3..9cc701f 100644 --- a/common/src/runMain.ts +++ b/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); diff --git a/common/src/utils/duration.ts b/common/src/utils/duration.ts index bf74ce8..7cac8d1 100644 --- a/common/src/utils/duration.ts +++ b/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; diff --git a/common/src/utils/index.ts b/common/src/utils/index.ts index 4271c83..c6a94f0 100644 --- a/common/src/utils/index.ts +++ b/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"; diff --git a/common/test/config.test.ts b/common/test/config.test.ts index 637a6e9..e3e21d1 100644 --- a/common/test/config.test.ts +++ b/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); +}); diff --git a/common/test/utils/duration.test.ts b/common/test/utils/duration.test.ts index 8a90090..8ce4050 100644 --- a/common/test/utils/duration.test.ts +++ b/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(); }); diff --git a/docker/src/config.ts b/docker/src/config.ts index d01afc4..eddb193 100644 --- a/docker/src/config.ts +++ b/docker/src/config.ts @@ -14,11 +14,10 @@ export const readConfig = (logger: Logger): DockerConfig => { run: getRunConfig(), failActionOnRunFailure: getFailActionOnRunFailureConfig(), waitForRunEnd: getWaitForRunEnd(), + runSummaryLoggingConfiguration: getRunSummaryLoggingConfiguration(), outputDotEnvPath: getOutputDotEnvPath() }; - logger.debug( - "Parsed configuration: " + JSON.stringify({ api: { ...config.api, apiToken: "*****" }, run: config.run }) - ); + logger.debug("Parsed configuration: " + JSON.stringify({ ...config, api: { ...config.api, apiToken: "*****" } })); return config; }; @@ -44,6 +43,33 @@ const getFailActionOnRunFailureConfig = (): boolean => const getWaitForRunEnd = (): boolean => getValidatedInput("WAIT_FOR_RUN_END", config.requiredBooleanValidation, "WAIT_FOR_RUN_END is required", "true"); +const getRunSummaryLoggingConfiguration = (): config.RunSummaryLoggingConfiguration => { + const enabled = getValidatedInput( + "RUN_SUMMARY_ENABLED", + config.requiredBooleanValidation, + "RUN_SUMMARY_ENABLED is required", + "true" + ); + const getIntervalInput = (name: string, validator: Validator, defaultValue: string) => + getValidatedInput(name, validator, `${name} must be a positive number`, defaultValue); + const initialRefreshInterval = getIntervalInput( + "RUN_SUMMARY_INITIAL_REFRESH_INTERVAL", + config.runSummaryRefreshIntervalValidation, + "5" + ); + const initialRefreshCount = getIntervalInput( + "RUN_SUMMARY_INITIAL_REFRESH_COUNT", + config.runSummaryInitialRefreshCountValidation, + "12" + ); + const refreshInterval = getIntervalInput( + "RUN_SUMMARY_REFRESH_INTERVAL", + config.runSummaryRefreshIntervalValidation, + "60" + ); + return { enabled, initialRefreshInterval, initialRefreshCount, refreshInterval }; +}; + const getApiConfig = (gatlingEnterpriseUrl: string): ApiClientConfig => { const apiToken = getValidatedInput( "GATLING_ENTERPRISE_API_TOKEN", diff --git a/gh-action/src/config.ts b/gh-action/src/config.ts index 3ba8d52..b485085 100644 --- a/gh-action/src/config.ts +++ b/gh-action/src/config.ts @@ -10,11 +10,10 @@ export const readConfig = (logger: Logger): config.Config => { api: getApiConfig(gatlingEnterpriseUrl), run: getRunConfig(), failActionOnRunFailure: getFailActionOnRunFailureConfig(), - waitForRunEnd: getWaitForRunEnd() + waitForRunEnd: getWaitForRunEnd(), + runSummaryLoggingConfiguration: getRunSummaryLoggingConfiguration() }; - logger.debug( - "Parsed configuration: " + JSON.stringify({ api: { ...config.api, apiToken: "*****" }, run: config.run }) - ); + logger.debug("Parsed configuration: " + JSON.stringify({ ...config, api: { ...config.api, apiToken: "*****" } })); return config; }; @@ -31,6 +30,26 @@ const getFailActionOnRunFailureConfig = (): boolean => const getWaitForRunEnd = (): boolean => getValidatedInput("wait_for_run_end", config.requiredBooleanValidation, "wait_for_run_end is required"); +const getRunSummaryLoggingConfiguration = (): config.RunSummaryLoggingConfiguration => { + const enabled = getValidatedInput( + "run_summary_enabled", + config.requiredBooleanValidation, + "run_summary_enabled is required" + ); + const getIntervalInput = (name: string, validator: Validator) => + getValidatedInput(name, validator, `${name} must be a positive number`); + const initialRefreshInterval = getIntervalInput( + "run_summary_initial_refresh_interval", + config.runSummaryRefreshIntervalValidation + ); + const initialRefreshCount = getIntervalInput( + "run_summary_initial_refresh_count", + config.runSummaryInitialRefreshCountValidation + ); + const refreshInterval = getIntervalInput("run_summary_refresh_interval", config.runSummaryRefreshIntervalValidation); + return { enabled, initialRefreshInterval, initialRefreshCount, refreshInterval }; +}; + const getApiConfig = (gatlingEnterpriseUrl: string): ApiClientConfig => { const apiToken = getValidatedInput( "api_token",