Intermittent test failures due to Vaults and Tasks in CI

[tegefaulkes]

Specification

Currently there are intermittent failures in the CI for the vaults domain and tasks domain. These need to be investigated and fixed up.

Test failures can be found at

1. https://gitlab.com/MatrixAI/open-source/Polykey/-/jobs/5691640837
2. https://gitlab.com/MatrixAI/open-source/Polykey/-/jobs/5689124352

The failures are as follows.

Details

Vaults domain failures

  ● VaultManager › with remote agents › can pull a cloned vault
    ErrorRPCHandlerFailed:
      373 |     // Rpc errors
      374 |     case 1:
    > 375 |       return new rpcErrors.ErrorRPCHandlerFailed();
          |              ^
      376 |     case 2:
      377 |       return new rpcErrors.ErrorRPCMessageLength();
      378 |     case 3:
      at constructor_.codeToReason (src/nodes/utils.ts:375:14)
      at constructor_.read (node_modules/@matrixai/quic/src/QUICStream.ts:423:31)
      at constructor_.read (node_modules/@matrixai/async-init/src/CreateDestroy.ts:203:18)
      at constructor_.processStreams (node_modules/@matrixai/quic/src/QUICConnection.ts:982:18)
      at node_modules/@matrixai/quic/src/QUICConnection.ts:812:14
      at node_modules/@matrixai/async-locks/src/Lock.ts:57:63
      at withF (node_modules/@matrixai/resources/src/utils.ts:24:18)
      at constructor_.recv (node_modules/@matrixai/quic/src/QUICConnection.ts:731:5)
      at Socket.handleSocketMessage (node_modules/@matrixai/quic/src/QUICSocket.ts:117:7)
  ● VaultManager › with remote agents › pullVault respects locking
    ErrorRPCHandlerFailed:
      373 |     // Rpc errors
      374 |     case 1:
    > 375 |       return new rpcErrors.ErrorRPCHandlerFailed();
          |              ^
      376 |     case 2:
      377 |       return new rpcErrors.ErrorRPCMessageLength();
      378 |     case 3:
      at constructor_.codeToReason (src/nodes/utils.ts:375:14)
      at constructor_.read (node_modules/@matrixai/quic/src/QUICStream.ts:423:31)
      at constructor_.read (node_modules/@matrixai/async-init/src/CreateDestroy.ts:203:18)
      at constructor_.processStreams (node_modules/@matrixai/quic/src/QUICConnection.ts:982:18)
      at node_modules/@matrixai/quic/src/QUICConnection.ts:812:14
      at node_modules/@matrixai/async-locks/src/Lock.ts:57:63
      at withF (node_modules/@matrixai/resources/src/utils.ts:24:18)
      at constructor_.recv (node_modules/@matrixai/quic/src/QUICConnection.ts:731:5)
      at Socket.handleSocketMessage (node_modules/@matrixai/quic/src/QUICSocket.ts:117:7)
  ● VaultManager › with remote agents › pullVault respects locking
    ErrorRPCHandlerFailed:
      373 |     // Rpc errors
      374 |     case 1:
    > 375 |       return new rpcErrors.ErrorRPCHandlerFailed();
          |              ^
      376 |     case 2:
      377 |       return new rpcErrors.ErrorRPCMessageLength();
      378 |     case 3:
      at constructor_.codeToReason (src/nodes/utils.ts:375:14)
      at constructor_.read (node_modules/@matrixai/quic/src/QUICStream.ts:423:31)
      at constructor_.read (node_modules/@matrixai/async-init/src/CreateDestroy.ts:203:18)
      at constructor_.processStreams (node_modules/@matrixai/quic/src/QUICConnection.ts:982:18)
      at node_modules/@matrixai/quic/src/QUICConnection.ts:812:14
      at node_modules/@matrixai/async-locks/src/Lock.ts:57:63
      at withF (node_modules/@matrixai/resources/src/utils.ts:24:18)
      at constructor_.recv (node_modules/@matrixai/quic/src/QUICConnection.ts:731:5)
      at Socket.handleSocketMessage (node_modules/@matrixai/quic/src/QUICSocket.ts:117:7)

tasks domain failures

  ● TaskManager › tasks persist between Tasks stop and starts
    ErrorTaskMissing: v0pbfqh89ilo0125nn2jk7sdm9g
      444 |                 signalHandler,
      445 |               );
    > 446 |               reject(new tasksErrors.ErrorTaskMissing(taskIdEncoded));
          |                      ^
      447 |             }
      448 |           },
      449 |           (reason) => {
      at src/tasks/TaskManager.ts:446:22
  ● TaskManager › tasks persist between Tasks stop and starts
    ErrorTaskManagerQueue:
      803 |       } catch (e) {
      804 |         this.queueLogger.error(`Failed queuing loop ${String(e)}`);
    > 805 |         throw new tasksErrors.ErrorTaskManagerQueue(undefined, { cause: e });
          |               ^
      806 |       }
      807 |     })();
      808 |     // Cancellation is always a resolution
      at src/tasks/TaskManager.ts:805:15
    Cause:
    ErrorDBTransactionRollbacked:
      789 |           this.queueLogger.debug(`Begin queuing loop iteration`);
      790 |           [this.queuingLockReleaser] = await this.queuingLock.lock(ctx)();
    > 791 |           await this.db.withTransactionF(async (tran) => {
          |           ^
      792 |             for await (const [kP] of tran.iterator(this.tasksQueuedDbPath, {
      793 |               values: false,
      794 |             })) {
      at constructor_.commit (node_modules/@matrixai/db/src/DBTransaction.ts:399:13)
      at constructor_.commit (node_modules/@matrixai/async-init/src/CreateDestroy.ts:148:20)
      at node_modules/@matrixai/db/src/DB.ts:232:26
      at withF (node_modules/@matrixai/resources/src/utils.ts:31:13)
      at src/tasks/TaskManager.ts:791:11
  ● TaskManager › tasks persist between Tasks stop and starts
    ErrorTaskManagerScheduler:
      741 |       } catch (e) {
      742 |         this.schedulerLogger.error(`Failed scheduling loop ${String(e)}`);
    > 743 |         throw new tasksErrors.ErrorTaskManagerScheduler(undefined, {
          |               ^
      744 |           cause: e,
      745 |         });
      746 |       }
      at src/tasks/TaskManager.ts:743:15
    Cause:
    ErrorDBNotRunning:
      703 |           const now =
      704 |             Math.trunc(performance.timeOrigin + performance.now()) + 100;
    > 705 |           await this.db.withTransactionF(async (tran) => {
          |                         ^
      706 |             // Queue up all the tasks that are scheduled to be executed before `now`
      707 |             for await (const [kP] of tran.iterator(this.tasksScheduledDbPath, {
      708 |               // Upper bound of `{lexi(TaskTimestamp + TaskDelay)}/{TaskId}`
      at constructor_.withTransactionF (node_modules/@matrixai/db/src/DB.ts:251:24)
      at withTransactionF (src/tasks/TaskManager.ts:705:25)

Tasks

1. determine causes and fix CI test failures

[CMCDragonkai]

I think this issue needs to be split up into bug issues.

Regarding the vaults tests, we need to consider the layers of stability. Starting from the transports, to the RPC, to the nodes domain, then finally the vaults domain. Any intermittent failure is likely to derive from that order.

So the vaults intermittent failures must start to be investigated from the bottom layer first. And generally speaking we need to eliminate sources of non-determinism. That means instead of sleeps, we need conditional promises. What we need to do here is:

1. Keep a timeout at a per-test function level.
2. Eliminate all other timeouts internally within each test, because they should just run and finish.
3. And then create additional layers of integration tests that do test the whole timeout situation. Keep these centralised either in a separate describe block or in a separate file.

As for the tasks domain, again that should be a separate bug issue.

Ultimately this is due to non-determinism in our tests, we need to basically eliminate them all, and whatever non-determinism that is left, separate them into a separate file so we can isolate those kinds of tests.

[CMCDragonkai]

@tegefaulkes can you split this up, and then close this issue.

[tegefaulkes]

For the task domain errors. It seems to be related to the DB mostly. I can reliably trigger one of them by stopping the DB before stopping the taskManager. So it's likely a problem with the tests not stopping things in the right order as a race condition.

I'm not sure how it's managing that, but I'm going to clean up the test structure a bit before really digging down into it.

[tegefaulkes]

Still getting the following after re-running the CI job a few times.

  ● TaskManager › tasks persist between Tasks stop and starts
    ErrorTaskMissing: v0piui90fjlo01ajjicps4ep46g
      444 |                 signalHandler,
      445 |               );
    > 446 |               reject(new tasksErrors.ErrorTaskMissing(taskIdEncoded));
          |                      ^
      447 |             }
      448 |           },
      449 |           (reason) => {
      at src/tasks/TaskManager.ts:446:22

[tegefaulkes]

Seems like there's a race condition. When creating a task with lazy: true a promise for the task completion is created. If there is no task in the DB then this promise will throw the above ErrorTaskMissing error. Looks like it's possible for the task inside the queue to be processed before the task promise is created leading to the error. I can force this to happen when scheduling a task by adding a sleep.

Seems to happen much more often on a slower system such as the CI job.

[tegefaulkes]

Never mind, I read the logic wrong, the tests were scheduling tasks with the taskPromise being acquired lazily.

[tegefaulkes]

Alright, everything looks good now. I ran the tasks domain test in CI about 6 times and had no failures. I think this is the last of the intermittent failures that are currently known about. I'll run all of the tests in the CI about 3 times as a sanity check. Any more than that would be a waste of credits I think.

After that its time to merge and call this done.