From 1cd7979c6357b4f9d7899f8c36ce12c4114de2b2 Mon Sep 17 00:00:00 2001 From: Peter Hedenskog Date: Fri, 15 May 2026 10:41:37 +0200 Subject: [PATCH] Capture finish time and failure reason on every test run MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The /admin "Recent failures" table reads straight from Bull's retained-failures list, which only sees jobs the testrunner threw — not test-level failures (sitespeed.io exits non-zero) or queue-down failures at submit time. The DB knows about all three modes via status='failed' but didn't store why a test failed or when it reached a terminal state, so the operator UI shows a health pill saying "1 failed in 24h" with an empty table underneath. Accurate but unactionable. This change makes the database authoritative for the failure picture. Two new columns are populated from every path that flips a row to 'failed' (Bull global:failed, queue-down submit, testrunner exit on the result queue), and finished_date is also stamped on completed runs so end-to-end and run-only durations become measurable — run_date today is the browsertime start timestamp, not finish. The follow-up that switches the admin table to read from the DB lands separately. The major bump is because existing deployments must run the included migration before rolling forward; it is metadata-only on Postgres 11+ so it runs in milliseconds, and ships with a sibling shell helper that wraps the docker-compose psql invocation. Co-authored-by: Claude noreply@anthropic.com --- CHANGELOG.md | 10 ++ .../migrations/001-add-failure-fields.sh | 118 ++++++++++++++++++ .../migrations/001-add-failure-fields.sql | 34 +++++ server/database/migrations/README.md | 79 ++++++++++++ server/database/setup/setup.sql | 4 +- server/src/database/index.js | 37 ++++-- server/src/server.js | 10 +- server/src/util/add-test.js | 4 +- .../src/testrunners/docker-testrunner.js | 25 +++- testrunner/src/testrunners/testrunner.js | 25 +++- 10 files changed, 327 insertions(+), 19 deletions(-) create mode 100755 server/database/migrations/001-add-failure-fields.sh create mode 100644 server/database/migrations/001-add-failure-fields.sql create mode 100644 server/database/migrations/README.md diff --git a/CHANGELOG.md b/CHANGELOG.md index 9a0abce0..4450f5e5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,16 @@ This changelog combines the server and testrunner changes. The changelog do [semantic versioning](https://semver.org). +## 4.0.0 - 2026-05-15 + +**Major bump because the database schema changes** — existing deployments must run `server/database/migrations/001-add-failure-fields.sh apply` (or the equivalent SQL by hand) against the live Postgres *before* rolling the server forward, otherwise the new `UPDATE` statements will fail. The migration is metadata-only on Postgres 11+ so it runs in milliseconds with no table rewrite. + +Schema and testrunner plumbing so `/admin` can stop relying on Bull's retained-failures list as the source of truth for failed tests. No user-visible UI change yet — that lands in the follow-up that switches the Recent failures table to the database. + +### Added +* New `failed_reason TEXT` and `finished_date TIMESTAMP` columns on `sitespeed_io_test_runs`. `failed_reason` is populated from three paths the DB previously knew nothing about: Bull's `global:failed` event (the testrunner threw), the queue-down submit path in `add-test.js` (Redis unreachable when the test was queued), and the result-queue path when sitespeed.io itself exits non-zero (testrunner now sends `Test runner exited with code N: `, capped at 500 chars). `finished_date` is stamped on every terminal transition, so end-to-end duration can be derived as `finished_date - added_date` and run duration as `finished_date - run_date` (which is the browsertime *start* timestamp, not finish) [#TBD](https://github.com/sitespeedio/onlinetest/pull/TBD). +* `server/database/migrations/` directory establishes the convention for schema changes against existing deployments — `setup.sql` only runs on a fresh Postgres data dir, so live databases need ALTERs applied separately. Each migration ships with a `.sh` helper (`check` / `backup` / `dry-run` / `apply` / `verify` / `rollback`) that runs `psql` inside the compose Postgres container, plus a README documenting the manual path. Existing deployments must run `001-add-failure-fields.sh apply` before rolling the server forward [#TBD](https://github.com/sitespeedio/onlinetest/pull/TBD). + ## 3.8.0 - 2026-05-15 Picks up sitespeed.io 41 as the default test engine, plus a `/admin` accuracy fix and a vendored compare-bundle refresh. diff --git a/server/database/migrations/001-add-failure-fields.sh b/server/database/migrations/001-add-failure-fields.sh new file mode 100755 index 00000000..0db5f92d --- /dev/null +++ b/server/database/migrations/001-add-failure-fields.sh @@ -0,0 +1,118 @@ +#!/usr/bin/env bash +# +# Helper for applying migration 001-add-failure-fields.sql against a +# Postgres instance running under docker compose. Each subcommand maps +# to one of the steps in server/database/migrations/README.md. +# +# Usage (run from the directory where you normally invoke `docker +# compose` for the stack — the script forwards $COMPOSE_FILE if set, +# so e.g. `COMPOSE_FILE=deploy/docker-compose.production.yml ./… apply` +# works for the prod compose file): +# +# ./001-add-failure-fields.sh check # confirm container + show current schema +# ./001-add-failure-fields.sh backup # pg_dump just this table to ./ +# ./001-add-failure-fields.sh dry-run # apply inside a tx + rollback +# ./001-add-failure-fields.sh apply # apply for real +# ./001-add-failure-fields.sh verify # show new schema + null counts +# ./001-add-failure-fields.sh rollback # drop the two columns +# +# Override the compose service name (defaults to `postgresql`) by +# exporting PG_SERVICE before running. + +set -euo pipefail + +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +SQL_FILE="$SCRIPT_DIR/001-add-failure-fields.sql" +PG_SERVICE="${PG_SERVICE:-postgresql}" + +# Pick `docker compose` (v2) over `docker-compose` (v1) when both +# exist; v2 is the default everywhere modern. Fail loudly if neither +# is on PATH so the operator gets an actionable error rather than a +# confusing one further down. +if docker compose version >/dev/null 2>&1; then + COMPOSE=(docker compose) +elif command -v docker-compose >/dev/null 2>&1; then + COMPOSE=(docker-compose) +else + echo "error: neither 'docker compose' nor 'docker-compose' found on PATH" >&2 + exit 1 +fi + +# Wrap psql so $POSTGRES_USER / $POSTGRES_DB expand inside the +# container (the postgres image sets those from your .env). -T on +# exec disables TTY allocation so stdin redirection works. +psql_in_container() { + "${COMPOSE[@]}" exec -T "$PG_SERVICE" \ + sh -c 'psql -v ON_ERROR_STOP=1 -U "$POSTGRES_USER" -d "$POSTGRES_DB"' "$@" +} + +cmd_check() { + echo "--- compose service status ---" + "${COMPOSE[@]}" ps "$PG_SERVICE" + echo + echo "--- current sitespeed_io_test_runs schema ---" + psql_in_container <<<'\d sitespeed_io_test_runs' +} + +cmd_backup() { + local out + out="sitespeed_io_test_runs-backup-$(date +%Y%m%d-%H%M%S).sql" + echo "Dumping table to $out ..." + "${COMPOSE[@]}" exec -T "$PG_SERVICE" \ + sh -c 'pg_dump -U "$POSTGRES_USER" -d "$POSTGRES_DB" -t sitespeed_io_test_runs' \ + > "$out" + echo "Done. Size: $(wc -c < "$out") bytes." +} + +cmd_dry_run() { + echo "Applying inside a transaction, then rolling back ..." + { + echo 'BEGIN;' + cat "$SQL_FILE" + echo '\d sitespeed_io_test_runs' + echo 'ROLLBACK;' + } | psql_in_container + echo + echo "Look for 'failed_reason | text' and 'finished_date | timestamp' in the schema printout above." + echo "The trailing 'ROLLBACK' confirms nothing was committed." +} + +cmd_apply() { + echo "Applying $SQL_FILE for real ..." + psql_in_container < "$SQL_FILE" + echo "Apply finished." +} + +cmd_verify() { + echo "--- post-migration schema ---" + psql_in_container <<<'\d sitespeed_io_test_runs' + echo + echo "--- null counts (both should be 0 until the new server is deployed) ---" + psql_in_container <<<'SELECT count(*) AS total, count(failed_reason) AS with_reason, count(finished_date) AS with_finish FROM sitespeed_io_test_runs;' +} + +cmd_rollback() { + echo "Dropping failed_reason and finished_date ..." + echo "WARNING: only safe if the new server has NOT been deployed yet." + echo "Press Ctrl-C within 5 seconds to abort." + sleep 5 + psql_in_container <<'SQL' +ALTER TABLE sitespeed_io_test_runs + DROP COLUMN IF EXISTS failed_reason, + DROP COLUMN IF EXISTS finished_date; +SQL + echo "Rollback finished." +} + +case "${1:-}" in + check) cmd_check ;; + backup) cmd_backup ;; + dry-run) cmd_dry_run ;; + apply) cmd_apply ;; + verify) cmd_verify ;; + rollback) cmd_rollback ;; + *) + echo "usage: $0 {check|backup|dry-run|apply|verify|rollback}" >&2 + exit 2 + ;; +esac diff --git a/server/database/migrations/001-add-failure-fields.sql b/server/database/migrations/001-add-failure-fields.sql new file mode 100644 index 00000000..732cd4cf --- /dev/null +++ b/server/database/migrations/001-add-failure-fields.sql @@ -0,0 +1,34 @@ +-- Adds two columns to sitespeed_io_test_runs. +-- +-- Apply with (see README.md in this directory for details): +-- +-- docker compose exec -T postgresql \ +-- sh -c 'psql -U "$POSTGRES_USER" -d "$POSTGRES_DB"' \ +-- < server/database/migrations/001-add-failure-fields.sql +-- +-- The sh -c wrapper is so $POSTGRES_USER / $POSTGRES_DB expand inside +-- the container (where the postgres image sets them) rather than from +-- the operator's host shell. +-- +-- Safe to run on a live DB before deploying the new server: both +-- columns are nullable with no default, so Postgres 11+ applies the +-- ALTER as a metadata-only change (no table rewrite). Existing reads +-- and writes continue to work because every other SQL statement names +-- its columns explicitly. +-- +-- failed_reason: free-text error captured when a test ends in status +-- 'failed'. Sources: Bull's global:failed event (the testrunner threw), +-- queue-down submit path in add-test.js, and (future) the result-queue +-- path when sitespeed.io itself reports a non-zero exit. +-- +-- finished_date: wall-clock timestamp of the terminal status transition +-- (completed or failed). Lets us measure end-to-end test duration as +-- finished_date - added_date and pure-run duration as +-- finished_date - run_date. Distinct from run_date, which is the +-- browsertime start timestamp reported by the testrunner. +-- +-- Both columns are nullable so existing rows stay valid without backfill. + +ALTER TABLE sitespeed_io_test_runs + ADD COLUMN failed_reason TEXT, + ADD COLUMN finished_date TIMESTAMP; diff --git a/server/database/migrations/README.md b/server/database/migrations/README.md new file mode 100644 index 00000000..15625fc0 --- /dev/null +++ b/server/database/migrations/README.md @@ -0,0 +1,79 @@ +# Database migrations + +`setup/setup.sql` only runs on a fresh Postgres data dir +(`docker-entrypoint-initdb.d`). For databases that already exist, apply +the SQL files in this directory in numeric order, once per environment. + +Each migration is designed to be: + +- **Forward-compatible** — the previous release of the server can still + run against the migrated schema. Migrate first, deploy after. +- **Online** — `ADD COLUMN` is nullable with no default so Postgres 11+ + applies it as a metadata-only change (no table rewrite, only a brief + metadata lock). Safe to run on a live database. + +## Easiest path: the helper script + +Each migration ships with a sibling `.sh` wrapper that runs against +the Postgres container in your compose stack. Run it from the +directory you normally use to invoke `docker compose`: + +```sh +./server/database/migrations/001-add-failure-fields.sh check # confirm container + show current schema +./server/database/migrations/001-add-failure-fields.sh backup # pg_dump just this table to ./ +./server/database/migrations/001-add-failure-fields.sh dry-run # apply inside a tx + rollback +./server/database/migrations/001-add-failure-fields.sh apply # apply for real +./server/database/migrations/001-add-failure-fields.sh verify # show new schema + null counts +./server/database/migrations/001-add-failure-fields.sh rollback # drop the two columns +``` + +If your prod stack is launched from `deploy/docker-compose.production.yml`, +either run the script from `deploy/` or export `COMPOSE_FILE` first: + +```sh +COMPOSE_FILE=deploy/docker-compose.production.yml \ + ./server/database/migrations/001-add-failure-fields.sh apply +``` + +Override the compose service name with `PG_SERVICE=...` if it isn't `postgresql`. + +## Applying a migration manually with the production Docker stack + +The Postgres container in `docker-compose.dependencies.yml` / +`deploy/docker-compose.production.yml` is named `postgresql`. The +official `postgres` image sets `POSTGRES_USER` and `POSTGRES_DB` +inside the container from the values you wired up in your `.env` +(`POSTGRESQL_USER`, `POSTGRESQL_DB`), so the simplest reliable form +is to let `psql` read those env vars from inside the container rather +than from your host shell: + +```sh +docker compose exec -T postgresql \ + sh -c 'psql -U "$POSTGRES_USER" -d "$POSTGRES_DB"' \ + < server/database/migrations/001-add-failure-fields.sql +``` + +(Substitute `docker-compose` for `docker compose` on older installs; +add `-f deploy/docker-compose.production.yml` if you run the prod +compose file directly. `-T` disables the TTY allocation so the file +on stdin is delivered verbatim.) + +To rehearse the change without committing it, wrap the SQL in a +transaction and roll back at the end: + +```sh +( echo 'BEGIN;'; \ + cat server/database/migrations/001-add-failure-fields.sql; \ + echo 'ROLLBACK;' ) | \ +docker compose exec -T postgresql \ + sh -c 'psql -v ON_ERROR_STOP=1 -U "$POSTGRES_USER" -d "$POSTGRES_DB"' +``` + +## Verifying + +```sh +docker compose exec postgresql \ + sh -c 'psql -U "$POSTGRES_USER" -d "$POSTGRES_DB" -c "\d sitespeed_io_test_runs"' +``` + +The new columns should appear at the bottom of the column list. diff --git a/server/database/setup/setup.sql b/server/database/setup/setup.sql index 36dfd109..5f4b5d66 100644 --- a/server/database/setup/setup.sql +++ b/server/database/setup/setup.sql @@ -18,7 +18,9 @@ CREATE TABLE sitespeed_io_test_runs ( browsertime_result JSONB, har JSON, configuration JSONB, - cli_params TEXT + cli_params TEXT, + failed_reason TEXT, + finished_date TIMESTAMP ); CREATE INDEX url_index ON sitespeed_io_test_runs (url); diff --git a/server/src/database/index.js b/server/src/database/index.js index 89b899a3..1ecb9a1b 100644 --- a/server/src/database/index.js +++ b/server/src/database/index.js @@ -58,12 +58,28 @@ export async function saveTest( } /** - * Update the status of the test + * Update the status of the test. When the new status is terminal + * (completed/failed) we also stamp finished_date so we can measure + * end-to-end duration; for failed transitions we capture the reason + * (Bull failedReason, caught error, etc.) so /admin can surface it + * without having to round-trip through Bull's retained-failures list. */ -export async function updateStatus(id, status) { +export async function updateStatus(id, status, reason) { logger.info('Update %s with %s', id, status); - const update = 'UPDATE sitespeed_io_test_runs SET status = $1 WHERE id = $2'; - const values = [status, id]; + let update; + let values; + if (status === 'failed') { + update = + 'UPDATE sitespeed_io_test_runs SET status = $1, finished_date = NOW(), failed_reason = $2 WHERE id = $3'; + values = [status, reason || undefined, id]; + } else if (status === 'completed') { + update = + 'UPDATE sitespeed_io_test_runs SET status = $1, finished_date = NOW() WHERE id = $2'; + values = [status, id]; + } else { + update = 'UPDATE sitespeed_io_test_runs SET status = $1 WHERE id = $2'; + values = [status, id]; + } try { await DatabaseHelper.getInstance().query(update, values); } catch (error) { @@ -107,7 +123,9 @@ export async function updateLabel(id, label) { } /** - * Update a test. + * Update a test. failedReason is the testrunner-supplied explanation + * (exit code + tail of stderr) when status='failed'; for 'completed' + * runs it is undefined and the column stays NULL. */ export async function updateTest( id, @@ -115,10 +133,14 @@ export async function updateTest( runTime, resultURL, browsertimeJSON, - har + har, + failedReason ) { + // finished_date = NOW() captures the wall-clock time the result + // landed in the DB; pair with added_date / run_date to measure queue + // wait and run duration. const update = - 'UPDATE sitespeed_io_test_runs SET status = $1, run_date = $2, result_url = $3, browsertime_result = $4, har = $5 WHERE id = $6'; + 'UPDATE sitespeed_io_test_runs SET status = $1, run_date = $2, result_url = $3, browsertime_result = $4, har = $5, finished_date = NOW(), failed_reason = $6 WHERE id = $7'; const values = [ status, @@ -126,6 +148,7 @@ export async function updateTest( resultURL, JSON.stringify(browsertimeJSON), JSON.stringify(har), + failedReason || undefined, id ]; try { diff --git a/server/src/server.js b/server/src/server.js index c2b21d33..c14e8e0f 100644 --- a/server/src/server.js +++ b/server/src/server.js @@ -30,8 +30,11 @@ async function setActiveStatus(jobid) { return updateStatus(jobid, 'active'); } -async function setFailedStatus(jobid) { - return updateStatus(jobid, 'failed'); +async function setFailedStatus(jobid, error) { + // Bull's global:failed event passes the failedReason string as the + // second argument — persist it so /admin can show why the job died + // even after Bull evicts the failed job per `removeOnFail`. + return updateStatus(jobid, 'failed', error); } function setupLogging() { @@ -47,7 +50,8 @@ async function setupResultQueue() { job.data.runTime, job.data.result.pageSummaryUrl, job.data.result.browsertime, - job.data.result.har + job.data.result.har, + job.data.failedReason ); const test = await getTest(job.data.id); diff --git a/server/src/util/add-test.js b/server/src/util/add-test.js index 6f7eac74..ddb5b0ca 100644 --- a/server/src/util/add-test.js +++ b/server/src/util/add-test.js @@ -238,7 +238,7 @@ export async function addTest(request) { `Setting status to failed for ${jobId} because queue is down`, error ); - await updateStatus(jobId, 'failed'); + await updateStatus(jobId, 'failed', error.message); throw new Error('Could not connect to queue'); } @@ -330,7 +330,7 @@ export async function addTestFromAPI( `Setting status to failed for ${jobId} because queue is down`, error ); - await updateStatus(jobId, 'failed'); + await updateStatus(jobId, 'failed', error.message); throw new Error('Could not connect to queue'); } diff --git a/testrunner/src/testrunners/docker-testrunner.js b/testrunner/src/testrunners/docker-testrunner.js index f02b56f2..2f7dc72f 100644 --- a/testrunner/src/testrunners/docker-testrunner.js +++ b/testrunner/src/testrunners/docker-testrunner.js @@ -126,7 +126,8 @@ export default async function runJob(job) { result: testResult.result, id: job.id, status: testResult.exitCode === 0 ? 'completed' : 'failed', - runTime + runTime, + failedReason: testResult.failedReason }, { removeOnComplete, @@ -213,6 +214,7 @@ async function runDocker( dockerLogger ) { let exitCode = 0; + let failedReason; try { const process = execa('docker', parameters); @@ -230,18 +232,35 @@ async function runDocker( } catch (error) { logger.error('Could not run Docker:' + error); exitCode = error.exitCode; + failedReason = buildFailedReason(error); } try { const result = await readFile(join(workingDirectory, resultFileName)); - return { result: JSON.parse(result.toString()), exitCode }; + return { result: JSON.parse(result.toString()), exitCode, failedReason }; } catch { - return { result: {}, exitCode }; + return { result: {}, exitCode, failedReason }; } finally { await cleanupWorkingDirectory(workingDirectory, logger); } } +// Same shape as the non-docker runner: exit code (always present) +// plus the last non-empty line of stderr when available. The wrapped +// process is sitespeed.io running inside the container, so its stderr +// surfaces here; if docker itself fails (image pull, daemon issues) +// the same path captures docker's stderr instead. +function buildFailedReason(error) { + const tail = (error.stderr || '') + .split('\n') + .map(line => line.trim()) + .findLast(Boolean); + let reason = `Test runner exited with code ${error.exitCode}`; + if (tail) reason += `: ${tail}`; + if (reason.length > 500) reason = reason.slice(0, 497) + '...'; + return reason; +} + async function cleanupWorkingDirectory(directory, logger) { try { await rm(directory, { recursive: true }); diff --git a/testrunner/src/testrunners/testrunner.js b/testrunner/src/testrunners/testrunner.js index 00f40cd4..eac0e0fb 100644 --- a/testrunner/src/testrunners/testrunner.js +++ b/testrunner/src/testrunners/testrunner.js @@ -55,7 +55,8 @@ export default async function runJob(job) { result: testResult.result, id: job.id, status: testResult.exitCode === 0 ? 'completed' : 'failed', - runTime + runTime, + failedReason: testResult.failedReason }, { removeOnComplete, @@ -156,6 +157,7 @@ async function runTest(job, workingDirectory, configFileName, logger) { } let exitCode = 0; + let failedReason; try { const process = execa(binary, parameters, environment); process.stdout.on('data', chunk => { @@ -173,17 +175,34 @@ async function runTest(job, workingDirectory, configFileName, logger) { logger.error(`Stdout: ${error.stdout}`); logger.error(`Stderr: ${error.stderr}`); exitCode = error.exitCode; + failedReason = buildFailedReason(error); } try { const result = await readFile( join(workingDirectory, `${job.queue.name}-${job.id}-result.json`) ); - return { result: JSON.parse(result.toString()), exitCode }; + return { result: JSON.parse(result.toString()), exitCode, failedReason }; } catch { - return { result: {}, exitCode }; + return { result: {}, exitCode, failedReason }; } } +// Build a short, single-line explanation of why the test runner +// exited non-zero, suitable for the failed_reason DB column. Prefer +// the last non-empty line of stderr (execa buffers stderr by default +// even when piped) but always include the exit code as a fallback — +// some failures produce no stderr output at all (kills, OOM, etc.). +function buildFailedReason(error) { + const tail = (error.stderr || '') + .split('\n') + .map(line => line.trim()) + .findLast(Boolean); + let reason = `Test runner exited with code ${error.exitCode}`; + if (tail) reason += `: ${tail}`; + if (reason.length > 500) reason = reason.slice(0, 497) + '...'; + return reason; +} + async function setupParameters(job, workingDirectory, configFileName) { let parameters = [ '--config',