refine the interaction between backups and main document connections (#…

…1461)

## Context

Recently we changed backups to use the main document connection, when
available, since then they can complete even while the document is
changing constantly. The system making the backups and the system
managing the document are quite loosely coupled, so the main document
connection can get closed at any time, even during a backup. The backup
process was written to expect this, but a problem appeared on the
closing side: SQLite will refuse to close if a backup is in progress,
and that error was entirely uncaught due to a missing await.

## Proposed solution

This adds the needed await. It also adds some explicit robustness on
both sides

## Related issues

#1380
#1427

## Has this been tested?

- [x] 👍 yes, I added tests to the test suite
- [ ] 💭 no, because this PR is a draft and still needs work
- [ ] 🙅 no, because this is not relevant here
- [ ] 🙋 no, because I need help <!-- Detail how we can help you -->

app/server/lib/HostedStorageManager.ts

@@ -758,7 +758,11 @@ export class HostedStorageManager implements IDocStorageManager {
     const docPath = this.getPath(docId);
     const tmpPath = `${docPath}-${postfix}`;
     const db = this._gristServer.getDocManager().getSQLiteDB(docId);
-    return backupSqliteDatabase(db, docPath, tmpPath, undefined, postfix, {docId});
+    return retryOnClose(
+      db,
+      (err) => this._log.debug(docId, `Problem making backup, will retry once because db closed: ${err}`),
+      () => backupSqliteDatabase(db, docPath, tmpPath, undefined, postfix, {docId})
+    );
   }
 
   /**
@@ -893,6 +897,34 @@ export class HostedStorageManager implements IDocStorageManager {
   }
 }
 
+/**
+ *
+ * Calls an operation with an optional database connection. If a
+ * database connection was supplied, and gets closed during the
+ * operation, and the operation failed, then we retry the operation,
+ * calling a logging function with the error.
+ *
+ * This is used for making backups, where we use a database connection
+ * handled externally if available. We can make the backup with or
+ * without that connection, but we should use it if available (so
+ * backups can terminate under constant changes made using that
+ * connection), which is how we got backed into this awkward retry corner.
+ *
+ */
+export async function retryOnClose<T>(db: SQLiteDB|undefined,
+                                      log: (err: Error) => void,
+                                      op: () => Promise<T>): Promise<T> {
+  const wasClosed = db?.isClosed();
+  try {
+    return await op();
+  } catch (err) {
+    if (wasClosed || !db?.isClosed()) {
+      throw err;
+    }
+    log(err);
+    return await op();
+  }
+}
 
 /**
  * Make a copy of a sqlite database safely and without locking it for long periods, using the
@@ -921,11 +953,17 @@ export async function backupSqliteDatabase(mainDb: SQLiteDB|undefined,
   let maxNonFinalStepTimeMs: number = 0;
   let finalStepTimeMs: number = 0;
   let numSteps: number = 0;
+  let backup: Backup|undefined = undefined;
   try {
     // NOTE: fse.remove succeeds also when the file does not exist.
     await fse.remove(dest);  // Just in case some previous process terminated very badly.
                              // Sqlite will try to open any existing material at this
                              // path prior to overwriting it.
+
+    // Ignore the supplied database connection if already closed.
+    if (mainDb?.isClosed()) {
+      mainDb = undefined;
+    }
     if (mainDb) {
       // We'll we working from an already configured SqliteDB interface,
       // don't need to do anything special.
@@ -943,7 +981,7 @@ export async function backupSqliteDatabase(mainDb: SQLiteDB|undefined,
     if (testProgress) { testProgress({action: 'open', phase: 'before'}); }
     // If using mainDb, it could close any time we yield and come back.
     if (mainDb?.isClosed()) { throw new Error('source closed'); }
-    const backup: Backup = mainDb ? mainDb.backup(dest) : db!.backup(src, 'main', 'main', false);
+    backup = mainDb ? mainDb.backup(dest) : db!.backup(src, 'main', 'main', false);
     if (testProgress) { testProgress({action: 'open', phase: 'after'}); }
     let remaining: number = -1;
     let prevError: Error|null = null;
@@ -971,7 +1009,7 @@ export async function backupSqliteDatabase(mainDb: SQLiteDB|undefined,
       let isCompleted: boolean = false;
       if (mainDb?.isClosed()) { throw new Error('source closed'); }
       try {
-        isCompleted = Boolean(await fromCallback(cb => backup.step(PAGES_TO_BACKUP_PER_STEP, cb)));
+        isCompleted = Boolean(await fromCallback(cb => backup!.step(PAGES_TO_BACKUP_PER_STEP, cb)));
       } catch (err) {
         if (String(err) !== String(prevError) || Date.now() - errorMsgTime > 1000) {
           _log.info(null, `error (${src} ${label}): ${err}`);
@@ -1005,6 +1043,7 @@ export async function backupSqliteDatabase(mainDb: SQLiteDB|undefined,
       await delay(PAUSE_BETWEEN_BACKUP_STEPS_IN_MS);
     }
   } finally {
+    if (backup) { await fromCallback(cb => backup!.finish(cb)); }
     if (testProgress) { testProgress({action: 'close', phase: 'before'}); }
     try {
       if (db) { await fromCallback(cb => db!.close(cb)); }

app/server/lib/SQLiteDB.ts

@@ -67,6 +67,7 @@
  * "migrations" array, and modifying create() to create correct new documents.
  */
 
+import {delay} from 'app/common/delay';
 import {ErrorWithCode} from 'app/common/ErrorWithCode';
 import {timeFormat} from 'app/common/timeFormat';
 import {create} from 'app/server/lib/create';
@@ -364,7 +365,31 @@ export class SQLiteDB implements ISQLiteDB {
     const alreadyClosed = this._closed;
     this._closed = true;
     if (!alreadyClosed) {
-      await this._db.close();
+      let tries: number = 0;
+      // We might not be able to close immediately if a backup is in
+      // progress. We will retry for about 10 seconds. Worst case is
+      // if a backup was in progress and is right at the last step of
+      // the backup and a lot of edits were made while the previous
+      // steps were in progress.
+      while (tries < 100) {
+        tries++;
+        try {
+          await this._db.close();
+          break;
+        } catch (e) {
+          if (String(e).match(/SQLITE_BUSY: unable to close due to unfinalized statements or unfinished backups/)) {
+            // Try again! now that this._closed is set, any pending backup should stop.
+            // It will stop quickly if in the middle of a backup, or more slowly if on
+            // the last step.
+            if (tries % 10 === 1) {
+              log.debug("SQLiteDB[%s]: waiting to close", this._dbPath);
+            }
+            await delay(100);
+          } else {
+            throw e;
+          }
+        }
+      }
       SQLiteDB._addOpens(this._dbPath, -1);
     }
   }

app/server/lib/SqliteCommon.ts

@@ -84,6 +84,7 @@ export interface Backup {
   failed: boolean;
   step(pages: number,
        callback?: (err: Error | null) => void): void;
+  finish(callback?: (err: Error | null) => void): void;
 }
 
 /**

app/server/lib/SqliteNode.ts

@@ -82,7 +82,7 @@ export class NodeSqlite3DatabaseAdapter implements MinDB {
   }
 
   public async close() {
-    this._db.close();
+    await fromCallback(cb => this._db.close(cb));
   }
 
   public async interrupt(): Promise<void> {

stubs/app/server/declarations.d.ts

@@ -12,6 +12,7 @@ declare module "@gristlabs/sqlite3" {
     public readonly completed: boolean;
     public readonly failed: boolean;
     public step(pages: number, callback?: (err: Error|null) => void): void;
+    public finish(callback?: (err: Error | null) => void): void;
   }
   export class DatabaseWithBackup extends Database {
     public backup(filename: string, callback?: (err: Error|null) => void): Backup;