Snap: start the database before backup and restore, and say why it does not answer.

wekan.database-restore and wekan.database-backup talked to whatever was
on the database port and nothing else. After `snap stop wekan`, which the
restore steps tell people to run, nothing is there; on a FerretDB snap the
database is its own service that starting WeKan alone does not bring back.
The tools then failed after a 30-second server-selection timeout with a
driver topology dump naming neither the service nor its log.

The new bin/database-ready asks bin/database-role which database holds
the data, starts that service when nothing answers, waits for it, and when
it still does not answer stops with the driver's own error and the
`snap logs` / `snap services` commands that show the reason. A "permission
denied" is explained as a security-policy denial on this system, not the
database, with the journal command that names the rule.

WeKan's own wait for FerretDB discarded the ping error, so its log said only
"FerretDB not ready yet" for every cause. db-eval now prints why a command
failed on stderr, and the wait's one-time hint shows it. The same hint
suggested `snap set wekan database=mongodb`, a setting the configure hook
removes, so that advice did nothing; it is gone.

The backup script also sources its settings and passes the archive path
quoted now, so a path with a space works.

tests/snapDatabaseRestore.test.cjs runs both scripts in a stand-in snap:
FerretDB or MongoDB started by role, a running database left alone, and,
negatively, a database that never answers stopping the tool before it
runs, with the error shown. A source guard requires both tools to wait for
the database first. tests/ferretdbWaitTimeout.test.cjs now requires the
ping error in the hint and rejects the removed setting. Not run inside an
installed snap here.

Thanks to fabiosalles and xet7 !

snap-src/bin/database-ready

@@ -0,0 +1,58 @@
+#!/bin/bash
+# database-ready — make sure the database WeKan's data is in answers, for the
+# commands an admin runs by hand (database-backup, database-restore).
+#
+# #6746: those commands talked to whatever was on $MONGODB_PORT and nothing
+# else. After `snap stop wekan` - which the restore steps people follow tell them
+# to do - nothing is, and on a FerretDB snap the database is a separate service
+# (wekan.ferretdb) that `snap start wekan.wekan` alone does not bring back. The
+# tools then failed after a 30-second server-selection timeout with a driver
+# topology dump that names neither the service nor where its log is.
+#
+# So: ask bin/database-role which database holds the data, start THAT service if
+# nothing answers, wait for it, and when it still does not answer, stop with the
+# driver's own error and the commands that show the reason.
+#
+# Source it, then:  database_ready HOST PORT   (returns 0 when it answers)
+
+database_ready() {
+  local host="$1" port="$2" url role svc waited err timeout
+  case "$host" in *:*) host="[$host]" ;; esac
+  url="mongodb://${host}:${port}/?directConnection=true"
+  # Older layouts and the tests' stand-in snap have no db-eval: leave the
+  # connection to the tool itself, as before.
+  [ -e "$SNAP/bin/db-eval" ] || return 0
+  bash "$SNAP/bin/db-eval" ping "$url" >/dev/null 2>&1 && return 0
+
+  role="$(bash "$SNAP/bin/database-role" 2>/dev/null)"
+  case "$role" in mongodb|ferretdb) ;; *) role=ferretdb ;; esac
+  svc="${SNAP_INSTANCE_NAME:-${SNAP_NAME:-wekan}}.${role}"
+  echo "No database answers on ${host}:${port}; starting ${svc}, which holds the data ..."
+  if ! snapctl start --enable "$svc" >/dev/null 2>&1; then
+    echo "Could not start ${svc} from here (run this command with sudo, or: sudo snap start ${svc})." >&2
+  fi
+
+  timeout="${WEKAN_DB_READY_TIMEOUT:-90}"
+  waited=0
+  until err="$(bash "$SNAP/bin/db-eval" ping "$url" 2>&1 >/dev/null)"; do
+    if [ "$waited" -ge "$timeout" ]; then
+      echo "" >&2
+      echo "The database (${svc}) does not answer on ${host}:${port} after ${timeout} seconds." >&2
+      [ -n "$err" ] && echo "  ${err}" >&2
+      case "$err" in
+        *"permission denied"*|*EACCES*|*"operation not permitted"*|*EPERM*)
+          echo "  The connection itself was refused by this system's security policy, not" >&2
+          echo "  by the database. 'sudo journalctl -k | grep -i denied' names the rule." >&2
+          ;;
+      esac
+      echo "The reason is in its log:" >&2
+      echo "  sudo snap logs -n 100 ${svc}" >&2
+      echo "  sudo snap services ${SNAP_INSTANCE_NAME:-${SNAP_NAME:-wekan}}" >&2
+      return 1
+    fi
+    sleep 2
+    waited=$((waited + 2))
+  done
+  echo "${svc} answers on ${host}:${port}."
+  return 0
+}

snap-src/bin/db-eval.mjs

@@ -207,6 +207,10 @@ try {
     console.log('ERROR:' + (e && e.message ? e.message : String(e)));
     code = 0;
   } else {
+    // #6746: say WHY. Every caller that polls redirects stderr, and the one
+    // that does not (bin/database-ready) shows it, so "permission denied" and
+    // "connection refused" stop looking identical.
+    console.error('db-eval ' + cmd + ': ' + (e && e.message ? e.message : String(e)));
     code = 1;
   }
 } finally {

snap-src/bin/mongodb-backup

@@ -5,7 +5,7 @@ if [[ "$PATH" != *"$SNAP_INSTANCE_NAME"* ]]; then
 fi
 
 # get wekan/mongo settings
-source $SNAP/bin/wekan-read-settings
+source "$SNAP/bin/wekan-read-settings"
 
 # make sure we have set minimum env variables for locale
 if [ -z "$LANG" ]; then
@@ -21,14 +21,18 @@ export LC_ALL=C
 export PATH=$SNAP/migratemongo/avx:$SNAP/usr/bin:$SNAP/bin:$PATH
 export LD_LIBRARY_PATH=$SNAP/lib:$SNAP/lib/x86_64-linux-gnu:$SNAP/lib/aarch64-linux-gnu:$LD_LIBRARY_PATH
 
-if [ -z $1 ]; then
+if [ -z "$1" ]; then
     DATE=`/bin/date +%Y%m%dT%H%M%S`
-    mkdir -p $SNAP_COMMON/db-backups/
-    ARCHIVE=$SNAP_COMMON/db-backups/wekan-$DATE.backup
+    mkdir -p "$SNAP_COMMON/db-backups/"
+    ARCHIVE="$SNAP_COMMON/db-backups/wekan-$DATE.backup"
 else
-    ARCHIVE=$1
+    ARCHIVE="$1"
 fi
 # start mongodb backup
 [ "x" == "x${MONGODB_BIND_IP}" ] && MONGODB_BIND_IP="127.0.0.1"
- echo "using bind ip"
-mongodump --host $MONGODB_BIND_IP --port $MONGODB_PORT -d wekan --gzip  --archive=${ARCHIVE}
+echo "using bind ip: $MONGODB_BIND_IP port: $MONGODB_PORT"
+# #6746: same as database-restore - back up the database that holds the data,
+# starting it first when it is stopped.
+source "$SNAP/bin/database-ready"
+database_ready "$MONGODB_BIND_IP" "$MONGODB_PORT" || exit 1
+mongodump --host "$MONGODB_BIND_IP" --port "$MONGODB_PORT" -d wekan --gzip "--archive=${ARCHIVE}"

snap-src/bin/mongodb-restore

@@ -34,6 +34,10 @@ fi
 
 [ "x" == "x${MONGODB_BIND_IP}" ] && MONGODB_BIND_IP="127.0.0.1"
 echo "using bind ip: $MONGODB_BIND_IP port: $MONGODB_PORT"
+# #6746: the database is a service of its own and is stopped after `snap stop
+# wekan`; start the one that holds the data and wait for it, or say why not.
+source "$SNAP/bin/database-ready"
+database_ready "$MONGODB_BIND_IP" "$MONGODB_PORT" || exit 1
 # --drop: drop each collection before restoring to avoid IndexKeySpecsConflict
 # when the dump's index specs differ from the existing index definitions
 # (e.g. unique flag mismatch after a schema migration).

snap-src/bin/wekan-control

@@ -544,9 +544,17 @@ if [ "ferretdb" = "${DATABASE}" ]; then
             echo "  - FerretDB left disabled/stopped (a failed migration hand-off):"
             echo "      snap start --enable ${WEKAN_SNAP_SVC}.ferretdb"
             echo ""
-            echo "To keep working on MongoDB instead while this is sorted out:"
-            echo "  snap set ${SNAP_NAME:-wekan} database=mongodb"
-            echo ""
+            # #6746: the ping above discards its error, so the log said only
+            # "not ready" - "permission denied" and "connection refused" looked
+            # the same. Ask once more and show what the driver says. (The
+            # `database` setting this used to suggest is gone: the configure
+            # hook unsets it, so that advice changed nothing.)
+            _ping_err="$("$DB_EVAL" ping "$DB_URL" 2>&1 >/dev/null)"
+            if [ -n "$_ping_err" ]; then
+                echo "The connection attempt says:"
+                echo "  $_ping_err"
+                echo ""
+            fi
             echo "Attachments and avatars are stored ON DISK under WRITABLE_PATH, NOT"
             echo "in the database ($SNAP_COMMON/files), so they are safe."
             echo "========================================================================"

tests/ferretdbWaitTimeout.test.cjs

@@ -54,8 +54,13 @@ test('the hint points to the FerretDB service log and the SQLite dir', () => {
     'must tell the admin where the real error is');
   assert.ok(ferretBranch.includes('$FERRETDB_SQLITE_DIR'),
     'must name the SQLite database directory to check for locks/corruption');
-  assert.ok(/database=mongodb/.test(ferretBranch),
-    'must offer the fallback to keep working on MongoDB');
+  // #6746: it used to offer `snap set wekan database=mongodb` as a fallback.
+  // That setting is gone (snap/hooks/configure unsets it), so the advice did
+  // nothing; the hint now shows the driver's own error instead.
+  assert.ok(!/database=mongodb/.test(ferretBranch),
+    'must not suggest the removed database setting');
+  assert.ok(/_ping_err="\$\("\$DB_EVAL" ping "\$DB_URL" 2>&1 >\/dev\/null\)"/.test(ferretBranch),
+    'must show why the connection failed, not only that it did');
 });
 
 test('it still keeps retrying after the hint (does not give up / crash)', () => {

tests/snapDatabaseRestore.test.cjs

@@ -8,6 +8,7 @@ const { spawnSync } = require('child_process');
 
 const root = path.join(__dirname, '..');
 const restore = path.join(root, 'snap-src', 'bin', 'mongodb-restore');
+const backup = path.join(root, 'snap-src', 'bin', 'mongodb-backup');
 let passed = 0;
 
 function test(name, fn) {
@@ -16,37 +17,86 @@ function test(name, fn) {
   console.log('  ok -', name);
 }
 
-function fixture() {
+// db: undefined = no db-eval in the snap (older layout); 'up' = answers at
+// once; 'after-start' = answers once snapctl started a service; 'never' =
+// never answers, failing the way #6746's reporter saw.
+function fixture({ db } = {}) {
   const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'wekan-restore-test-'));
   const snap = path.join(dir, 'snap fixture');
+  const common = path.join(dir, 'common');
   const fakeBin = path.join(snap, 'migratemongo', 'avx');
+  const hostBin = path.join(dir, 'host-bin');
   fs.mkdirSync(path.join(snap, 'bin'), { recursive: true });
   fs.mkdirSync(fakeBin, { recursive: true });
+  fs.mkdirSync(common, { recursive: true });
+  fs.mkdirSync(hostBin, { recursive: true });
+  for (const name of ['database-ready', 'database-role']) {
+    fs.copyFileSync(path.join(root, 'snap-src', 'bin', name), path.join(snap, 'bin', name));
+  }
   fs.writeFileSync(
     path.join(snap, 'bin', 'wekan-read-settings'),
     'MONGODB_BIND_IP=127.0.0.9\nMONGODB_PORT=27099\n',
   );
   const capture = path.join(dir, 'captured.json');
+  const snapctlLog = path.join(dir, 'snapctl.log');
+  const started = path.join(dir, 'started');
+  for (const tool of ['mongorestore', 'mongodump']) {
+    fs.writeFileSync(
+      path.join(fakeBin, tool),
+      `#!/bin/bash\nprintf '%s\\n' ${tool} "$@" > "$RESTORE_CAPTURE"\n`,
+      { mode: 0o755 },
+    );
+  }
+  if (db) {
+    const answers = { up: 'true', 'after-start': '[ -f "$DB_STARTED" ]', never: 'false' }[db];
+    fs.writeFileSync(
+      path.join(snap, 'bin', 'db-eval'),
+      '#!/bin/bash\n' +
+      `if ${answers}; then exit 0; fi\n` +
+      'echo "db-eval ping: connection(127.0.0.9:27099[-62]) unable to write wire message to network: write tcp 127.0.0.1:53014->127.0.0.9:27099: write: permission denied" >&2\n' +
+      'exit 1\n',
+      { mode: 0o755 },
+    );
+  }
   fs.writeFileSync(
-    path.join(fakeBin, 'mongorestore'),
-    '#!/bin/bash\nprintf \'%s\\n\' "$@" > "$RESTORE_CAPTURE"\n',
+    path.join(hostBin, 'snapctl'),
+    '#!/bin/bash\nprintf \'%s\\n\' "$*" >> "$SNAPCTL_LOG"\ntouch "$DB_STARTED"\n',
     { mode: 0o755 },
   );
-  return { dir, snap, capture };
+  return { dir, snap, common, hostBin, capture, snapctlLog, started };
 }
 
-function run(f, args) {
-  return spawnSync('bash', [restore, ...args], {
+function run(f, args, script = restore) {
+  return spawnSync('bash', [script, ...args], {
     encoding: 'utf8',
     env: {
       ...process.env,
+      PATH: `${f.hostBin}:${process.env.PATH}`,
       SNAP: f.snap,
+      SNAP_COMMON: f.common,
       SNAP_INSTANCE_NAME: 'wekan',
+      SNAP_NAME: 'wekan',
       RESTORE_CAPTURE: f.capture,
+      SNAPCTL_LOG: f.snapctlLog,
+      DB_STARTED: f.started,
+      WEKAN_DB_READY_TIMEOUT: '0',
     },
   });
 }
 
+function captured(f) {
+  return fs.readFileSync(f.capture, 'utf8').trim().split('\n');
+}
+
+function snapctlCalls(f) {
+  return fs.existsSync(f.snapctlLog) ? fs.readFileSync(f.snapctlLog, 'utf8').trim().split('\n') : [];
+}
+
+function withFixture(opts, fn) {
+  const f = fixture(opts);
+  try { fn(f); } finally { fs.rmSync(f.dir, { recursive: true, force: true }); }
+}
+
 test('#6547 restores by replacing existing collections with --drop', () => {
   const f = fixture();
   try {
@@ -55,8 +105,9 @@ test('#6547 restores by replacing existing collections with --drop', () => {
     const result = run(f, [archive]);
     assert.strictEqual(result.status, 0, result.stderr);
     assert.deepStrictEqual(
-      fs.readFileSync(f.capture, 'utf8').trim().split('\n'),
+      captured(f),
       [
+        'mongorestore',
         '--host',
         '127.0.0.9',
         '--port',
@@ -98,4 +149,81 @@ test('negative: a nonexistent archive fails before mongorestore', () => {
   }
 });
 
+test('#6746 restore starts the stopped FerretDB service before mongorestore', () => {
+  withFixture({ db: 'after-start' }, (f) => {
+    const archive = path.join(f.dir, 'wekan.backup');
+    fs.writeFileSync(archive, 'fixture');
+    const result = run(f, [archive]);
+    assert.strictEqual(result.status, 0, result.stderr);
+    // A fresh FerretDB snap: no MongoDB files, so the data is FerretDB's.
+    assert.deepStrictEqual(snapctlCalls(f), ['start --enable wekan.ferretdb']);
+    assert.match(result.stdout, /wekan\.ferretdb answers on 127\.0\.0\.9:27099/);
+    assert.strictEqual(captured(f)[0], 'mongorestore');
+  });
+});
+
+test('#6746 restore starts MongoDB instead while a migration is still owed', () => {
+  withFixture({ db: 'after-start' }, (f) => {
+    fs.writeFileSync(path.join(f.common, 'WiredTiger'), 'mongo files');
+    const archive = path.join(f.dir, 'wekan.backup');
+    fs.writeFileSync(archive, 'fixture');
+    const result = run(f, [archive]);
+    assert.strictEqual(result.status, 0, result.stderr);
+    assert.deepStrictEqual(snapctlCalls(f), ['start --enable wekan.mongodb']);
+  });
+});
+
+test('#6746 a database that already answers is not restarted', () => {
+  withFixture({ db: 'up' }, (f) => {
+    const archive = path.join(f.dir, 'wekan.backup');
+    fs.writeFileSync(archive, 'fixture');
+    const result = run(f, [archive]);
+    assert.strictEqual(result.status, 0, result.stderr);
+    assert.deepStrictEqual(snapctlCalls(f), []);
+    assert.strictEqual(captured(f)[0], 'mongorestore');
+  });
+});
+
+test('negative #6746: a database that never answers stops restore with the reason', () => {
+  withFixture({ db: 'never' }, (f) => {
+    const archive = path.join(f.dir, 'wekan.backup');
+    fs.writeFileSync(archive, 'fixture');
+    const result = run(f, [archive]);
+    assert.strictEqual(result.status, 1);
+    assert.strictEqual(fs.existsSync(f.capture), false, 'mongorestore must not run');
+    assert.match(result.stderr, /wekan\.ferretdb\) does not answer on 127\.0\.0\.9:27099/);
+    assert.match(result.stderr, /write: permission denied/, 'the driver error must be shown');
+    assert.match(result.stderr, /security policy/, 'permission denied must be explained');
+    assert.match(result.stderr, /sudo snap logs -n 100 wekan\.ferretdb/);
+  });
+});
+
+test('#6746 backup starts the database and dumps it; negative: not when it never answers', () => {
+  withFixture({ db: 'after-start' }, (f) => {
+    const archive = path.join(f.dir, 'out with spaces.backup');
+    const result = run(f, [archive], backup);
+    assert.strictEqual(result.status, 0, result.stderr);
+    assert.deepStrictEqual(snapctlCalls(f), ['start --enable wekan.ferretdb']);
+    assert.deepStrictEqual(captured(f), [
+      'mongodump', '--host', '127.0.0.9', '--port', '27099', '-d', 'wekan', '--gzip',
+      `--archive=${archive}`,
+    ]);
+  });
+  withFixture({ db: 'never' }, (f) => {
+    const result = run(f, [path.join(f.dir, 'x.backup')], backup);
+    assert.strictEqual(result.status, 1);
+    assert.strictEqual(fs.existsSync(f.capture), false, 'mongodump must not run');
+    assert.match(result.stderr, /sudo snap logs -n 100 wekan\.ferretdb/);
+  });
+});
+
+test('negative #6746: no snap database tool connects before database_ready', () => {
+  for (const [file, tool] of [[restore, 'mongorestore'], [backup, 'mongodump']]) {
+    const text = fs.readFileSync(file, 'utf8');
+    const ready = text.indexOf('database_ready "$MONGODB_BIND_IP" "$MONGODB_PORT" || exit 1');
+    const call = text.search(new RegExp(`^${tool} `, 'm'));
+    assert.ok(ready > 0 && call > ready, `${path.basename(file)} must wait for the database before ${tool}`);
+  }
+});
+
 console.log(`\nsnapDatabaseRestore: all ${passed} tests passed`);