diff --git a/.github/workflows/db-migrations.yml b/.github/workflows/db-migrations.yml deleted file mode 100644 index 78f8b0361..000000000 --- a/.github/workflows/db-migrations.yml +++ /dev/null @@ -1,51 +0,0 @@ -name: Database Migrations - -on: - pull_request: - paths: - - .github/workflows/db-migrations.yml - - lib/bin/create-docker-databases.js - - lib/model/migrations/** - - test/db-migrations/** - - package.json - - package-lock.json - - Makefile - push: - paths: - - .github/workflows/db-migrations.yml - - lib/bin/create-docker-databases.js - - lib/model/migrations/** - - test/db-migrations/** - - package.json - - package-lock.json - - Makefile - -jobs: - db-migration-tests: - timeout-minutes: 2 - # TODO should we use the same container as circle & central? - runs-on: ubuntu-latest - services: - # see: https://docs.github.com/en/enterprise-server@3.5/actions/using-containerized-services/creating-postgresql-service-containers - postgres: - image: postgres:14.20 - env: - POSTGRES_PASSWORD: odktest - ports: - - 5432:5432 - # Set health checks to wait until postgres has started - options: >- - --health-cmd pg_isready - --health-interval 1s - --health-timeout 5s - --health-retries 50 - steps: - - uses: actions/checkout@v6 - - name: Set node version - uses: actions/setup-node@v6 - with: - node-version-file: package.json - cache: 'npm' - - run: npm ci - - run: node lib/bin/create-docker-databases.js - - run: make test-db-migrations diff --git a/.github/workflows/oidc-e2e.yml b/.github/workflows/oidc-e2e.yml deleted file mode 100644 index 5b5851459..000000000 --- a/.github/workflows/oidc-e2e.yml +++ /dev/null @@ -1,49 +0,0 @@ -name: OIDC e2e tests - -on: - push: - pull_request: - -env: - DEBUG: pw:api - ODK_PLAYWRIGHT_BROWSERS: chromium,firefox,webkit - -jobs: - oidc-e2e-test: - timeout-minutes: 6 - # TODO should we use the same container as circle & central? - runs-on: ubuntu-latest - services: - # see: https://docs.github.com/en/enterprise-server@3.5/actions/using-containerized-services/creating-postgresql-service-containers - postgres: - image: postgres:14.20 - env: - POSTGRES_PASSWORD: odktest - ports: - - 5432:5432 - # Set health checks to wait until postgres has started - options: >- - --health-cmd pg_isready - --health-interval 1s - --health-timeout 5s - --health-retries 50 - steps: - - # This one weird trick speeds up every build! - # see: https://github.com/getodk/central-backend/pull/1642 - # see: https://github.com/actions/runner/issues/4030 - - run: sudo apt-get remove --purge man-db - - - uses: actions/checkout@v6 - - name: Set node version - uses: actions/setup-node@v6 - with: - node-version-file: package.json - cache: 'npm' - - run: make test-oidc-e2e - - name: Archive Playwright Test Report - if: failure() - uses: actions/upload-artifact@v4 - with: - name: Playwright Test Report - path: test/e2e/oidc/playwright-tests/results/html-report/ diff --git a/.github/workflows/oidc-integration.yml b/.github/workflows/oidc-integration.yml deleted file mode 100644 index b38e1a7e0..000000000 --- a/.github/workflows/oidc-integration.yml +++ /dev/null @@ -1,39 +0,0 @@ -name: OIDC integration tests - -on: - push: - pull_request: - -jobs: - oidc-integration-test: - timeout-minutes: 6 - # TODO should we use the same container as circle & central? - runs-on: ubuntu-latest - services: - # see: https://docs.github.com/en/enterprise-server@3.5/actions/using-containerized-services/creating-postgresql-service-containers - postgres: - image: postgres:14.20 - env: - POSTGRES_PASSWORD: odktest - ports: - - 5432:5432 - # Set health checks to wait until postgres has started - options: >- - --health-cmd pg_isready - --health-interval 1s - --health-timeout 5s - --health-retries 50 - steps: - - uses: actions/checkout@v6 - - name: Set node version - uses: actions/setup-node@v6 - with: - node-version-file: package.json - cache: 'npm' - - run: npm ci - - run: FAKE_OIDC_ROOT_URL=http://localhost:9898 make fake-oidc-server-ci > fake-oidc-server.log & - - run: node lib/bin/create-docker-databases.js - - run: make test-oidc-integration - - name: Fake OIDC Server Logs - if: always() - run: "! [[ -f ./fake-oidc-server.log ]] || cat ./fake-oidc-server.log" diff --git a/.github/workflows/s3-e2e.yml b/.github/workflows/s3-e2e.yml deleted file mode 100644 index 0fad3c5e5..000000000 --- a/.github/workflows/s3-e2e.yml +++ /dev/null @@ -1,39 +0,0 @@ -name: S3 E2E Tests - -on: - push: - pull_request: - -jobs: - s3-e2e: - timeout-minutes: 15 - # TODO should we use the same container as circle & central? - runs-on: ubuntu-latest - services: - # see: https://docs.github.com/en/enterprise-server@3.5/actions/using-containerized-services/creating-postgresql-service-containers - postgres: - image: postgres:14.20 - env: - POSTGRES_PASSWORD: odktest - ports: - - 5432:5432 - # Set health checks to wait until postgres has started - options: >- - --health-cmd pg_isready - --health-interval 1s - --health-timeout 5s - --health-retries 50 - steps: - - uses: actions/checkout@v6 - - run: make fake-s3-server-persistent - - name: Set node version - uses: actions/setup-node@v6 - with: - node-version-file: package.json - cache: 'npm' - - run: npm ci - - run: node lib/bin/create-docker-databases.js - - run: sudo apt-get install wait-for-it - - name: E2E Test - timeout-minutes: 10 - run: ./test/e2e/s3/run-tests.sh diff --git a/.github/workflows/soak-test.yml b/.github/workflows/soak-test.yml index 2215a73d7..197596655 100644 --- a/.github/workflows/soak-test.yml +++ b/.github/workflows/soak-test.yml @@ -1,11 +1,15 @@ name: Soak Test on: - push: - branches: master + pull_request: jobs: soak-test: + strategy: + fail-fast: true + matrix: + x: [ 1, 2, 3, 4, 5, 6, 7, 8, 9, 10 ] + y: [ 1, 2, 3, 4, 5, 6, 7, 8, 9, 10 ] timeout-minutes: 15 # TODO should we use the same container as circle & central? runs-on: ubuntu-latest diff --git a/.github/workflows/standard-e2e.yml b/.github/workflows/standard-e2e.yml deleted file mode 100644 index caa0adb63..000000000 --- a/.github/workflows/standard-e2e.yml +++ /dev/null @@ -1,55 +0,0 @@ -name: Standard E2E Tests - -on: - push: - pull_request: - -env: - LOG_LEVEL: DEBUG - -jobs: - standard-e2e: - timeout-minutes: 15 - # TODO should we use the same container as circle & central? - runs-on: ubuntu-latest - services: - # see: https://docs.github.com/en/enterprise-server@3.5/actions/using-containerized-services/creating-postgresql-service-containers - postgres: - image: postgres:14.20 - env: - POSTGRES_PASSWORD: odktest - ports: - - 5432:5432 - # Set health checks to wait until postgres has started - options: >- - --health-cmd pg_isready - --health-interval 1s - --health-timeout 5s - --health-retries 50 - steps: - - uses: actions/checkout@v6 - - name: Set node version - uses: actions/setup-node@v6 - with: - node-version-file: package.json - cache: 'npm' - - run: npm ci - - run: node lib/bin/create-docker-databases.js - - - name: E2E Test - timeout-minutes: 10 - run: ./test/e2e/standard/run-tests.sh - - - uses: ./.github/actions/install-postgres-client - with: - postgres-version: 14 - - name: Grant postgres superuser role - # As per #1368, this role is required to create the pgrowlocks extension - run: psql -c 'ALTER ROLE jubilant SUPERUSER' postgresql://postgres:odktest@localhost/postgres - - name: Backup/restore tests - timeout-minutes: 10 - run: ./test/e2e/standard/backup-restore.sh - - - name: Backend Logs - if: always() - run: "! [[ -f ./server.log ]] || cat ./server.log" diff --git a/.github/workflows/standard-suite.yml b/.github/workflows/standard-suite.yml deleted file mode 100644 index 767167d53..000000000 --- a/.github/workflows/standard-suite.yml +++ /dev/null @@ -1,37 +0,0 @@ -name: Full Standard Test Suite - -on: - push: - pull_request: - -jobs: - standard-tests: - timeout-minutes: 20 - # TODO should we use the same container as circle & central? - runs-on: ubuntu-latest - services: - # see: https://docs.github.com/en/enterprise-server@3.5/actions/using-containerized-services/creating-postgresql-service-containers - postgres: - image: postgres:14.20 - env: - POSTGRES_PASSWORD: odktest - ports: - - 5432:5432 - # Set health checks to wait until postgres has started - options: >- - --health-cmd pg_isready - --health-interval 1s - --health-timeout 5s - --health-retries 50 - steps: - - uses: actions/checkout@v6 - - name: Set node version - uses: actions/setup-node@v6 - with: - node-version-file: package.json - cache: 'npm' - - run: make check-for-large-files - - run: npm ci - - run: make api-docs-lint - - run: node lib/bin/create-docker-databases.js - - run: make test diff --git a/.gitignore b/.gitignore index 9f3cf8fba..d2842f92e 100644 --- a/.gitignore +++ b/.gitignore @@ -13,6 +13,7 @@ node_modules/ .vscode /junit-reports/ /config/development.json +/gha-logs/ # context files for AI agents AGENTS.md diff --git a/analyse-queries.js b/analyse-queries.js new file mode 100755 index 000000000..d5c90ca5e --- /dev/null +++ b/analyse-queries.js @@ -0,0 +1,57 @@ +#!/usr/bin/env node + +const { execSync } = require('node:child_process'); +const { readdirSync, readFileSync } = require('node:fs'); + +const log = (...args) => console.log('[analyse-queries]', ...args); + +const rootDir = './gha-logs'; + +const [,,...args] = process.argv; +const runId = args.length ? args[0] : execSync(`ls -td ${rootDir}/* | head -1`, { encoding:'utf8' }).substring(rootDir.length + 1).trim(); +log('run id:', runId); + +const allActiveQueries = {}; + +for( const att of readdirSync(`${rootDir}/run-${runId}`)) { + for(const _f of readdirSync(`${rootDir}/run-${runId}/${att}`)) { + const f = `${rootDir}/run-${runId}/${att}/${_f}`; + log('Processing:', f); + + const queryPrefix = 'Open queries: '; + const activeQueries = readFileSync(f, 'utf8') + .split('\n') + .filter(it => it.includes(queryPrefix)) + .map(it => { + const [ prefix, json ] = it.split(queryPrefix); + return JSON.parse(json) + .filter(it => it.state !== 'idle') + .map(q => { + const logged_at = new Date(prefix.match(/2026-\S*Z/)[0]); + const query_start = new Date(q.query_start); + return { + ...q, + logged_at, + query_start, + duration_so_far: logged_at.valueOf() - query_start.valueOf(), + }; + }); + }); + + const lastQueries = activeQueries.at(-1); + log(' last activeQueries:', lastQueries); + + activeQueries + .flat() + .forEach(processQuery); + } + + log(' Done.'); +} + +console.log('allActiveQueries:', JSON.stringify(allActiveQueries, null, 2)); + +function processQuery({ state, duration_so_far, query }) { + if(!allActiveQueries[query]) allActiveQueries[query] = duration_so_far; + allActiveQueries[query] = Math.max(allActiveQueries[query], duration_so_far); +} diff --git a/dump-github-job-logs.sh b/dump-github-job-logs.sh new file mode 100755 index 000000000..d569d7355 --- /dev/null +++ b/dump-github-job-logs.sh @@ -0,0 +1,73 @@ +#!/bin/bash -eu +log() { echo >&2 "[$(basename "$0")] $*"; } + +if [[ $# -gt 0 ]] && [[ $1 = --help ]]; then + cat < "$logDir/$safeName.log" + done +done + + +log "All done." diff --git a/lib/model/query/client-audits.js b/lib/model/query/client-audits.js index c208d4eec..26a960b78 100644 --- a/lib/model/query/client-audits.js +++ b/lib/model/query/client-audits.js @@ -20,6 +20,7 @@ const existsForBlob = (blobId) => ({ maybeOne }) => .then((x) => x.isDefined()); const streamForExport = (formId, draft, keyIds, options = QueryOptions.none) => ({ s3, stream }) => stream(sql` + -- ClientAudits.streamForExport() select client_audits.*, blobs.id AS "blobId", blobs.s3_status, blobs.content, blobs.sha, submissions."instanceId", "localKey", "keyId", index, submissions."instanceId" from submission_defs inner join (select id, "submitterId", "createdAt", "updatedAt", "instanceId", "reviewState" from submissions diff --git a/lib/model/query/submission-attachments.js b/lib/model/query/submission-attachments.js index da7e41e2a..23b9aa47e 100644 --- a/lib/model/query/submission-attachments.js +++ b/lib/model/query/submission-attachments.js @@ -220,6 +220,7 @@ const getByFormAndInstanceIdAndName = (formId, instanceId, name, draft) => ({ ma // EXPORT const streamForExport = (formId, draft, keyIds, options = QueryOptions.none) => ({ s3, stream }) => stream(sql` + -- SubmissionAttachments.streamForExport() select submission_attachments.name, blobs.id AS "blobId", blobs.content, blobs.s3_status, blobs.sha, submission_attachments.index, form_defs."keyId", submissions."instanceId", submission_defs."localKey" from submission_defs inner join (select * from submissions where draft=${draft}) as submissions on submissions.id=submission_defs."submissionId" diff --git a/lib/model/query/submissions.js b/lib/model/query/submissions.js index 1e055974d..e7dc269be 100644 --- a/lib/model/query/submissions.js +++ b/lib/model/query/submissions.js @@ -190,6 +190,7 @@ const setSelectMultipleValues = (formId, submissionDefId, pairs) => ({ run }) => }; const getSelectMultipleValuesForExport = (formId, draft, options) => ({ all }) => all(sql` + -- Submissions.getSelectMultipleValuesForExport() select path, value from form_field_values inner join (select id, "submissionId" from submission_defs @@ -422,9 +423,10 @@ const _exportFields = unjoiner(ExportSubmission, ExportSubmissionDef, Submission Actor.alias('actors', 'submitter'), Frame.define(table('attachments'), 'present', 'expected'), Frame.define(table('edits'), 'count'), Submission.Exports).fields; -const _export = (formId, draft, keyIds = [], options) => { +const _export = (caller, formId, draft, keyIds = [], options) => { const encrypted = keyIds.length !== 0; return sql` + -- ${sql.identifier(['Submissions', caller])}() select ${_exportFields} from submission_defs inner join (select * from submissions where draft=${draft}) as submissions on submissions.id=submission_defs."submissionId" @@ -466,12 +468,12 @@ ${page(options)}`; }; const streamForExport = (formId, draft, keyIds, options = QueryOptions.none) => ({ s3, stream }) => - stream(_export(formId, draft, keyIds, options)) + stream(_export('streamForExport', formId, draft, keyIds, options)) .then(dbStream => streamEncBlobs(s3, dbStream)) .then(stream.map(_exportUnjoiner)); const getForExport = (formId, instanceId, draft, options = QueryOptions.none) => ({ maybeOne }) => - maybeOne(_export(formId, draft, [], options.withCondition({ 'submissions.instanceId': instanceId }))) + maybeOne(_export('getForExport', formId, draft, [], options.withCondition({ 'submissions.instanceId': instanceId }))) .then(map(_exportUnjoiner)); //////////////////////////////////////////////////////////////////////////////// @@ -546,6 +548,7 @@ select count(*) from deleted_submissions`); // Etag-deriving functions const getODataSelectionEtag = (formId, draft, options = QueryOptions.none) => ({ db }) => db.oneFirst(sql` + -- Submissios.getODataSelectionEtag() WITH selection AS ( SELECT event FROM submissions diff --git a/test/e2e/soak/ci/run-tests.sh b/test/e2e/soak/ci/run-tests.sh index b83f18fc5..e3c66945a 100755 --- a/test/e2e/soak/ci/run-tests.sh +++ b/test/e2e/soak/ci/run-tests.sh @@ -32,7 +32,7 @@ if ! curl -s -o /dev/null "$serverUrl"; then fi log 'Checking open DB query count...' -timeout 120 bash -c "cd ../../..; while ! node lib/bin/check-open-db-queries.js; do sleep 1; done" +timeout 600 bash -c "cd ../../..; while ! node lib/bin/check-open-db-queries.js; do sleep 1; done" log 'Checking backend is serving requests...' responseLog="$(mktemp)" diff --git a/test/e2e/soak/index.js b/test/e2e/soak/index.js index f6836f176..f3d0247aa 100644 --- a/test/e2e/soak/index.js +++ b/test/e2e/soak/index.js @@ -56,7 +56,15 @@ async function soakTest() { log.info('Setup complete. Starting soak tests...'); - await doSoakTest('randomSubmission', 50, 1_000, 30_000, 100, n => randomSubmission(n, projectId, formId)); + await doSoakTest({ + name: 'randomSubmission', + throughput: 50, + throughputPeriod: 1_000, + testDuration: 30_000, + maxDrainDuration: 30_000, + minimumSuccessThreshold: 100, + fn: n => randomSubmission(n, projectId, formId), + }); // TODO work out a more scientific sleep duration const backgroundJobPause = 20_000; @@ -64,7 +72,15 @@ async function soakTest() { await new Promise(resolve => { setTimeout(resolve, backgroundJobPause); }); log.info('Woke up.'); - await doSoakTest('exportZipWithDataAndMedia', 10, 3_000, 300_000, 0, n => exportZipWithDataAndMedia(n, projectId, formId)); + await doSoakTest({ + name: 'exportZipWithDataAndMedia', + throughput: 10, + throughputPeriod: 3_000, + testDuration: 300_000, + maxDrainDuration: 240_000, + minimumSuccessThreshold: 0, + fn: n => exportZipWithDataAndMedia(n, projectId, formId), + }); log.info(`Check for extra logs at ${logPath}`); @@ -74,12 +90,17 @@ async function soakTest() { process.exit(0); } -function doSoakTest(name, throughput, throughputPeriod, testDuration, minimumSuccessThreshold, fn) { +async function doSoakTest({ name, throughput, throughputPeriod, testDuration, maxDrainDuration, minimumSuccessThreshold, fn }) { log.info('Starting soak test:', name); log.info(' throughput:', throughput, 'per period'); log.info(' throughputPeriod:', throughputPeriod, 'ms'); log.info(' testDuration:', durationForHumans(testDuration)); log.info('-------------------------------'); + log.info('Checking endpoint responding ok...'); + const firstSize = await fn(-1); + log.info(' 1st response size:', firstSize); + log.info('-------------------------------'); + let openRequests = 0; return new Promise((resolve, reject) => { try { const successes = []; @@ -93,8 +114,11 @@ function doSoakTest(name, throughput, throughputPeriod, testDuration, minimumSuc const iterate = async () => { const n = iterationCount++; const started = Date.now(); + const nonce = Math.floor(Math.random() * Number.MAX_SAFE_INTEGER); try { + log.info(`iterate(${nonce}) requesting; openRequests: ${++openRequests}`); const size = await fn(n); + log.info(`iterate(${nonce}) returned: ${size} bytes`); const finished = Date.now(); const time = finished - started; successes.push(time); @@ -104,6 +128,8 @@ function doSoakTest(name, throughput, throughputPeriod, testDuration, minimumSuc fails.push(err.message); results[n] = { success:false, started, finished:Date.now(), err:{ message:err.message, stack:err.stack } }; } finally { + --openRequests; + log.info(`iterate(${nonce}) completed; openRequests: ${--openRequests}`); ++completedIterations; } }; @@ -114,7 +140,6 @@ function doSoakTest(name, throughput, throughputPeriod, testDuration, minimumSuc setTimeout(async () => { clearTimeout(timerId); - const maxDrainDuration = 120_000; await new Promise(resolve => { log.info(`Waiting up to ${durationForHumans(maxDrainDuration)} for test drainage...`); const maxDrainTimeout = Date.now() + maxDrainDuration; @@ -168,6 +193,7 @@ function doSoakTest(name, throughput, throughputPeriod, testDuration, minimumSuc resolve(); }, +testDuration); } catch(err) { + log('Err caught:', err); reject(err); } }); @@ -187,7 +213,7 @@ function reportWarning(message) { log.report('--------------------------'); } -function randomSubmission(n, projectId, formId) { +async function randomSubmission(n, projectId, formId) { const headers = { 'Content-Type': 'multipart/form-data; boundary=foo', 'X-OpenRosa-Version': '1.0', @@ -204,15 +230,25 @@ ${submissionTemplate \r --foo--`; - return api.apiPostAndDump('randomSubmission', n, `projects/${projectId}/forms/${formId}/submissions`, body, headers); + try { + return await api.apiPostAndDump('randomSubmission', n, `projects/${projectId}/forms/${formId}/submissions`, body, headers); + } catch(err) { + log('Err in randomSubmission()', err); + throw err; + } } function randInt() { return Math.floor(Math.random() * 9999); } -function exportZipWithDataAndMedia(n, projectId, formId) { - return api.apiGetToFile('exportZipWithDataAndMedia', n, `projects/${projectId}/forms/${formId}/submissions.csv.zip?splitSelectMultiples=true&groupPaths=true&deletedFields=true`); +async function exportZipWithDataAndMedia(n, projectId, formId) { + try { + return await api.apiGetToFile('exportZipWithDataAndMedia', n, `projects/${projectId}/forms/${formId}/submissions.csv.zip?splitSelectMultiples=true&groupPaths=true&deletedFields=true`); + } catch(err) { + log('Err in exportZipWithDataAndMedia()', err); + throw err; + } } function durationForHumans(ms) {