demo race condition in Actor.del()

.github/workflows/actor-race-1.yml

@@ -0,0 +1,40 @@
+name: Actors race condition 1 demo
+
+on:
+  push:
+  pull_request:
+
+jobs:
+  actor-race-1:
+    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.10
+        env:
+          POSTGRES_PASSWORD: odktest
+        ports:
+          - 5432:5432
+        # Set health checks to wait until postgres has started
+        options: >-
+          --health-cmd pg_isready
+          --health-interval 10s
+          --health-timeout 5s
+          --health-retries 5
+    steps:
+    - uses: actions/checkout@v4
+    - name: Set node version
+      uses: actions/setup-node@v4
+      with:
+        node-version: 22.16.0
+        cache: 'npm'
+    - run: npm ci
+    - run: node lib/bin/create-docker-databases.js
+    - name: Demonstrate the issue
+      timeout-minutes: 10
+      run: ./test/e2e/actor-race-1/ci
+    - name: Backend Logs
+      if: always()
+      run: "! [[ -f ./backend.log ]] || cat ./backend.log"

.github/workflows/actor-race-2.yml

@@ -0,0 +1,40 @@
+name: Actors race condition 2 demo
+
+on:
+  push:
+  pull_request:
+
+jobs:
+  actor-race-2:
+    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.10
+        env:
+          POSTGRES_PASSWORD: odktest
+        ports:
+          - 5432:5432
+        # Set health checks to wait until postgres has started
+        options: >-
+          --health-cmd pg_isready
+          --health-interval 10s
+          --health-timeout 5s
+          --health-retries 5
+    steps:
+    - uses: actions/checkout@v4
+    - name: Set node version
+      uses: actions/setup-node@v4
+      with:
+        node-version: 22.16.0
+        cache: 'npm'
+    - run: npm ci
+    - run: node lib/bin/create-docker-databases.js
+    - name: Demonstrate the issue
+      timeout-minutes: 10
+      run: ./test/e2e/actor-race-2/ci
+    - name: Backend Logs
+      if: always()
+      run: "! [[ -f ./backend.log ]] || cat ./backend.log"

test/e2e/actor-race-1/.gitignore

@@ -0,0 +1 @@
+/logs/

test/e2e/actor-race-1/ci

@@ -0,0 +1,60 @@
+#!/bin/bash -eu
+set -o pipefail
+
+serverUrl="http://localhost:8383"
+userEmail="x@example.com"
+userPassword="secret1234"
+
+log() {
+  echo "[test/e2e/actor-race-1] $*"
+}
+
+fail_job() {
+  log 'Job failed.'
+  exit 1
+}
+
+make base
+
+echo "$userPassword" | node ./lib/bin/cli.js user-create  -u "$userEmail"
+node ./lib/bin/cli.js user-promote -u "$userEmail"
+
+make run >backend.log 2>&1 &
+
+log 'Waiting for backend to start...'
+timeout 30 bash -c "while ! curl -s -o /dev/null $serverUrl; do sleep 1; done"
+log 'Backend started!'
+
+cd test/e2e/actor-race-1
+node index.js -s "$serverUrl" -P "$userPassword" -L /tmp/actor-race-1-tester-logs
+
+if ! curl -s -o /dev/null "$serverUrl"; then
+  log 'Backend died.'
+  fail_job
+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"
+
+log 'Checking backend is serving requests...'
+responseLog="$(mktemp)"
+requestBody='{"email":"'"$userEmail"'","password":"'"$userPassword"'"}'
+loginStatus="$(curl -s -o "$responseLog" -w '%{http_code}' \
+  --header 'Content-Type: application/json' --data "$requestBody" \
+  "$serverUrl/v1/sessions"
+)"
+if [[ "$loginStatus" != "200" ]]; then
+  log 'Backend behaving badly:'
+  log "$(cat "$responseLog")"
+  fail_job
+fi
+log 'Backend survived; job passed.'
+
+# TODO upload results to getodk.cloud for graphing.  Include:
+#
+# * key metrics (for graphing against other branches)
+#   * throughput
+#   * average response time
+#   * response time range (quickest, slowest)
+#   * did export response sizes vary?
+# * individual response timings (to see if e.g. response times degrade over time)

test/e2e/actor-race-1/index.js

@@ -0,0 +1,139 @@
+// Copyright 2022 ODK Central Developers
+// See the NOTICE file at the top-level directory of this distribution and at
+// https://github.com/getodk/central-backend/blob/master/NOTICE.
+// This file is part of ODK Central. It is subject to the license terms in
+// the LICENSE file found in the top-level directory of this distribution and at
+// https://www.apache.org/licenses/LICENSE-2.0. No part of ODK Central,
+// including this file, may be copied, modified, propagated, or distributed
+// except according to the terms contained in the LICENSE file.
+
+const fs = require('node:fs');
+const { program } = require('commander');
+
+const SUITE_NAME = 'test/e2e/soak';
+const log = require('../util/logger')(SUITE_NAME);
+const { apiClient } = require('../util/api');
+
+program
+    .option('-s, --server-url <serverUrl>', 'URL of ODK Central server', 'http://localhost:8989')
+    .option('-u, --user-email <userEmail>', 'Email of central user', 'x@example.com')
+    .option('-P, --user-password <userPassword>', 'Password of central user', 'secret')
+    .option('-f, --form-path <formPath>', 'Path to form file (XML, XLS, XLSX etc.)', './250q-form.xml')
+    .option('-L, --log-directory <log-directory>', 'Log output directory (this should be an empty or non-existent directory)')
+    ;
+program.parse();
+const { serverUrl, userEmail, userPassword, formPath, logDirectory } = program.opts();
+
+log(`Using form: ${formPath}`);
+log(`Connecting to ${serverUrl} with user ${userEmail}...`);
+
+const logPath = logDirectory || `./logs/${new Date().toISOString()}`;
+
+let api;
+
+soakTest();
+
+async function soakTest() {
+  log.info('Setting up...');
+
+  const execId = Math.floor(Math.random() * Number.MAX_SAFE_INTEGER);
+
+  log.info('Creating log directory:', logPath, '...');
+  fs.mkdirSync(logPath, { recursive:true });
+
+  api = await apiClient(SUITE_NAME, { serverUrl, userEmail, userPassword, logPath });
+
+  const roles = await api.apiGet('roles');
+  console.log('roles:', roles);
+  const roleIds = roles
+      .filter(r => !['admin', 'pwreset', 'pub-link'].includes(r.system))
+      .map(r => r.id);
+  console.log('roleIds:', roleIds);
+
+  const initialCount = await dbCount(`SELECT COUNT(*) FROM actors AS count`);
+  log.info('initialCount:', initialCount);
+
+  const actorCount = 10;
+
+  // TODO create a load of Actors
+  const actorCreations = [];
+  for(let i=0; i<actorCount; ++i) {
+    const uniq = `condemned-actor-${execId}-${i}`;
+    const creation = api
+        .apiPostJson('users', {
+          email: `condemned-actor-${execId}-${i}@example.test`,
+          password: uniq,
+        })
+        .then(res => res.id);
+    actorCreations.push(creation);
+  }
+  const actors = await Promise.all(actorCreations);
+  console.log('actors:', actors);
+
+  const finalCount = await dbCount(`SELECT COUNT(*) FROM actors AS count`);
+  log.info('finalCount:', finalCount);
+
+  const createdCount = finalCount - initialCount;
+  if(createdCount !== actorCount) throw new Error(`Expected ${actorCount} actors, but got ${createdCount}`);
+
+  // simultaneously:
+  // * assign all the roles to all the actors
+  // * delete all the actors
+  await Promise.all(actors.flatMap(id => [
+    ...roleIds.map(roleId => withRandomDelay(async () => {
+      try {
+        return await api.apiPost(`assignments/${roleId}/${id}`);
+      } catch(err) {
+        if(err.responseStatus !== 404) throw err;
+      }
+    })),
+    withRandomDelay(() => api.apiDelete(`users/${id}`)),
+  ]));
+
+  // check for assignments to deleted actors
+  const count = await countAssignedButDeletedActors();
+  if(count !== 0) throw new Error(`There are ${count} assignments for deleted actors.`);
+
+  log.info(`Check for extra logs at ${logPath}`);
+
+  log.info('Complete.');
+
+  // force exit in case some promise somewhere has failed to resolved (somehow required in Github Actions)
+  process.exit(0);
+}
+
+async function dbQuery(sqlQuery) {
+  const client = new (require('pg').Client)(require('../../../config/default.json').default.database);
+  await client.connect();
+
+  const { rows } = await client.query(sqlQuery);
+
+  return rows;
+}
+
+async function withRandomDelay(fn) {
+  await sleep(randInt(10));
+  return fn();
+}
+
+async function dbCount(sqlQuery) {
+  const [ { count } ] = await dbQuery(sqlQuery);
+  return +count;
+}
+
+function countAssignedButDeletedActors() {
+  return dbCount(`
+    SELECT COUNT(*) AS count
+      FROM assignments
+      JOIN actors AS actors ON actors.id=assignments."actorId"
+      WHERE actors."deletedAt" IS NOT NULL
+  `);
+}
+
+function randInt(max=9999) {
+  return Math.floor(Math.random() * max);
+}
+
+function sleep(ms) {
+  return new Promise(resolve => setTimeout(resolve, ms)); // eslint-disable-line no-promise-executor-return
+}

test/e2e/actor-race-2/.gitignore

@@ -0,0 +1 @@
+/logs/

test/e2e/actor-race-2/ci

@@ -0,0 +1,60 @@
+#!/bin/bash -eu
+set -o pipefail
+
+serverUrl="http://localhost:8383"
+userEmail="x@example.com"
+userPassword="secret1234"
+
+log() {
+  echo "[test/e2e/actor-race-2] $*"
+}
+
+fail_job() {
+  log 'Job failed.'
+  exit 1
+}
+
+make base
+
+echo "$userPassword" | node ./lib/bin/cli.js user-create  -u "$userEmail"
+node ./lib/bin/cli.js user-promote -u "$userEmail"
+
+make run >backend.log 2>&1 &
+
+log 'Waiting for backend to start...'
+timeout 30 bash -c "while ! curl -s -o /dev/null $serverUrl; do sleep 1; done"
+log 'Backend started!'
+
+cd test/e2e/actor-race-2
+node index.js -s "$serverUrl" -P "$userPassword" -L /tmp/actor-race-2-tester-logs
+
+if ! curl -s -o /dev/null "$serverUrl"; then
+  log 'Backend died.'
+  fail_job
+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"
+
+log 'Checking backend is serving requests...'
+responseLog="$(mktemp)"
+requestBody='{"email":"'"$userEmail"'","password":"'"$userPassword"'"}'
+loginStatus="$(curl -s -o "$responseLog" -w '%{http_code}' \
+  --header 'Content-Type: application/json' --data "$requestBody" \
+  "$serverUrl/v1/sessions"
+)"
+if [[ "$loginStatus" != "200" ]]; then
+  log 'Backend behaving badly:'
+  log "$(cat "$responseLog")"
+  fail_job
+fi
+log 'Backend survived; job passed.'
+
+# TODO upload results to getodk.cloud for graphing.  Include:
+#
+# * key metrics (for graphing against other branches)
+#   * throughput
+#   * average response time
+#   * response time range (quickest, slowest)
+#   * did export response sizes vary?
+# * individual response timings (to see if e.g. response times degrade over time)