Bug: active mirror jobs are incorrectly treated as interrupted; middleware starts overlapping recovery attempt #150

New Issue

2026-10-05T01:44:57+02:00

adam commented

2026-10-05 01:44:57 +02:00

Version

Observed on v3.29.0 (local checkout commit b1d2ea4).

Summary

A mirror/sync job that is still legitimately running can be immediately classified as “interrupted.” Middleware then launches recovery for the live job. If that recovery takes longer than 15 seconds, middleware times out without cancelling the recovery, releases its request-level lock, and later requests initiate additional attempts.

This produces repeated log messages such as:

Middleware detected jobs needing recovery mid-run
Attempting recovery from middleware...
Recovery already in progress, skipping...
Middleware recovery completed with some issues

It is a reliability issue because the application may simultaneously run normal work and recovery work against the same job/repository, while the scheduler advances nextRun and does not retry until the normal schedule.

Reproduction

Configure a user with GitHub and Gitea credentials.
Start a mirror or sync job, including a single small repository.
While it is processing, make an application request. Enabling the UI’s LIVE button makes this easy because it refreshes registered data every 3 seconds while the tab is visible.
Observe that middleware detects the still-running job as requiring recovery.
If recovery lasts longer than 15 seconds, observe the timeout. Continue using the UI / allow health checks to run.
Observe further attempts logging Recovery already in progress, skipping..., followed by Middleware recovery completed with some issues.

Actual behavior

A newly started job has inProgress=true and lastCheckpoint=null.
The recovery detector treats any lastCheckpoint=null as an interrupted job immediately, regardless of how recently it started.
Middleware tries to resume the still-live job.
The 15-second middleware timeout does not cancel initializeRecovery().
Middleware clears recoveryInFlight after timeout while recovery is still running, allowing later requests to call initializeRecovery() again.
The recovery module’s process-local recoveryInProgress guard rejects these later calls, producing misleading “completed with some issues” logs.
The scheduler continues running, but skips the user until the persisted nextRun. This can make sync appear to have stopped until the next scheduled time.

Expected behavior

A job should not be eligible for recovery merely because it has not completed its first item.
Recovery should never run concurrently with legitimate active work on the same job.
A request timeout must not leave uncancelled recovery running while allowing another request to start a new attempt.
A failed or interrupted scheduled sync should have a clear retry strategy rather than only waiting for the regular nextRun.

Source-level cause

1. False-positive interrupted-job detection

createMirrorJob() creates active jobs with no initial checkpoint:

src/lib/helpers.ts, around lines 63–66:

inProgress: inProgress !== undefined ? inProgress : false,
startedAt: inProgress ? currentTimestamp : undefined,
completedAt: undefined,
lastCheckpoint: undefined,

findInterruptedJobs() then matches any in-progress job with a null checkpoint:

src/lib/helpers.ts, around lines 243–255:

and(
  eq(mirrorJobs.inProgress, true),
  or(
    or(isNull(mirrorJobs.lastCheckpoint), lt(mirrorJobs.lastCheckpoint, cutoffTime)),
    lt(mirrorJobs.startedAt, staleCutoffTime)
  )
)

The isNull(lastCheckpoint) branch has no age/grace-period check. Therefore a brand-new job is considered interrupted before it has completed its first item.

Checkpoint updates happen only on completion/progress, so a long individual mirror/sync operation can again become eligible after the 10-minute cutoff.

2. Middleware timeout abandons, rather than cancels, recovery

Middleware races recovery against a 15-second timeout:

src/middleware.ts, around lines 152–162:

const recoveryResult = await Promise.race([
  initializeRecovery({ ... }),
  new Promise<boolean>((_, reject) => {
    setTimeout(() => reject(new Error('Middleware recovery timeout')), 15000);
  })
]);

The losing initializeRecovery() promise continues running. Its module-level flag remains true:

src/lib/recovery.ts, around lines 90–106:

if (recoveryInProgress) {
  console.log('Recovery already in progress, skipping...');
  return false;
}

recoveryInProgress = true;

But middleware always releases its separate recoveryInFlight flag in finally:

src/middleware.ts, around lines 176–186.

Subsequent UI, health-check, or API requests can therefore attempt recovery again while the first recovery is still active.

3. Scheduler is alive but deliberately deferred

The scheduler persists the next execution time before running the sync:

src/lib/scheduler-service.ts, around lines 92–97.

It then skips until that time:

src/lib/scheduler-service.ts, around lines 811–818:

if (scheduleConfig.nextRun && new Date(scheduleConfig.nextRun) > currentTime) {
  console.log(`[Scheduler] Skipping user ${config.userId} - next run at ${scheduleConfig.nextRun}`);
  continue;
}

Therefore repeated “Skipping user … next run at …” lines mean the scheduler loop is still running; they do not mean it crashed.

Proposed fix

Require an age check for a null checkpoint:

or(
  and(
    isNull(mirrorJobs.lastCheckpoint),
    lt(mirrorJobs.startedAt, cutoffTime),
  ),
  lt(mirrorJobs.lastCheckpoint, cutoffTime),
  lt(mirrorJobs.startedAt, staleCutoffTime),
)

Set an initial checkpoint/heartbeat when creating an in-progress job, and refresh it during long-running item processing—not only after item completion.
Add an atomic database-backed recovery claim/lease for a job before resuming it. A module-level boolean cannot safely coordinate job ownership or distinguish an active job from an abandoned one.
Do not execute full recovery from request middleware. Use a dedicated recovery worker/startup process. If middleware keeps a bounded wait, it must keep the in-flight state tied to the underlying recovery promise until that promise settles.
Adjust scheduling so a failed/interrupted scheduled sync is retried appropriately instead of only waiting for the ordinary nextRun.

Impact

This can cause duplicate or conflicting mirror/sync activity, misleading recovery logs, and a silent delay in future scheduled work. The UI’s LIVE mode and health checks make it more visible because they generate requests frequently, but they are not the root cause.

### Version Observed on `v3.29.0` (local checkout commit `b1d2ea4`). ### Summary A mirror/sync job that is still legitimately running can be immediately classified as “interrupted.” Middleware then launches recovery for the live job. If that recovery takes longer than 15 seconds, middleware times out without cancelling the recovery, releases its request-level lock, and later requests initiate additional attempts. This produces repeated log messages such as: ```text Middleware detected jobs needing recovery mid-run Attempting recovery from middleware... Recovery already in progress, skipping... Middleware recovery completed with some issues ``` It is a reliability issue because the application may simultaneously run normal work and recovery work against the same job/repository, while the scheduler advances `nextRun` and does not retry until the normal schedule. ### Reproduction 1. Configure a user with GitHub and Gitea credentials. 2. Start a mirror or sync job, including a single small repository. 3. While it is processing, make an application request. Enabling the UI’s `LIVE` button makes this easy because it refreshes registered data every 3 seconds while the tab is visible. 4. Observe that middleware detects the still-running job as requiring recovery. 5. If recovery lasts longer than 15 seconds, observe the timeout. Continue using the UI / allow health checks to run. 6. Observe further attempts logging `Recovery already in progress, skipping...`, followed by `Middleware recovery completed with some issues`. ### Actual behavior - A newly started job has `inProgress=true` and `lastCheckpoint=null`. - The recovery detector treats any `lastCheckpoint=null` as an interrupted job immediately, regardless of how recently it started. - Middleware tries to resume the still-live job. - The 15-second middleware timeout does not cancel `initializeRecovery()`. - Middleware clears `recoveryInFlight` after timeout while recovery is still running, allowing later requests to call `initializeRecovery()` again. - The recovery module’s process-local `recoveryInProgress` guard rejects these later calls, producing misleading “completed with some issues” logs. - The scheduler continues running, but skips the user until the persisted `nextRun`. This can make sync appear to have stopped until the next scheduled time. ### Expected behavior - A job should not be eligible for recovery merely because it has not completed its first item. - Recovery should never run concurrently with legitimate active work on the same job. - A request timeout must not leave uncancelled recovery running while allowing another request to start a new attempt. - A failed or interrupted scheduled sync should have a clear retry strategy rather than only waiting for the regular `nextRun`. ### Source-level cause #### 1. False-positive interrupted-job detection `createMirrorJob()` creates active jobs with no initial checkpoint: - `src/lib/helpers.ts`, around lines 63–66: ```ts inProgress: inProgress !== undefined ? inProgress : false, startedAt: inProgress ? currentTimestamp : undefined, completedAt: undefined, lastCheckpoint: undefined, ``` `findInterruptedJobs()` then matches any in-progress job with a null checkpoint: - `src/lib/helpers.ts`, around lines 243–255: ```ts and( eq(mirrorJobs.inProgress, true), or( or(isNull(mirrorJobs.lastCheckpoint), lt(mirrorJobs.lastCheckpoint, cutoffTime)), lt(mirrorJobs.startedAt, staleCutoffTime) ) ) ``` The `isNull(lastCheckpoint)` branch has no age/grace-period check. Therefore a brand-new job is considered interrupted before it has completed its first item. Checkpoint updates happen only on completion/progress, so a long individual mirror/sync operation can again become eligible after the 10-minute cutoff. #### 2. Middleware timeout abandons, rather than cancels, recovery Middleware races recovery against a 15-second timeout: - `src/middleware.ts`, around lines 152–162: ```ts const recoveryResult = await Promise.race([ initializeRecovery({ ... }), new Promise<boolean>((_, reject) => { setTimeout(() => reject(new Error('Middleware recovery timeout')), 15000); }) ]); ``` The losing `initializeRecovery()` promise continues running. Its module-level flag remains true: - `src/lib/recovery.ts`, around lines 90–106: ```ts if (recoveryInProgress) { console.log('Recovery already in progress, skipping...'); return false; } recoveryInProgress = true; ``` But middleware always releases its separate `recoveryInFlight` flag in `finally`: - `src/middleware.ts`, around lines 176–186. Subsequent UI, health-check, or API requests can therefore attempt recovery again while the first recovery is still active. #### 3. Scheduler is alive but deliberately deferred The scheduler persists the next execution time before running the sync: - `src/lib/scheduler-service.ts`, around lines 92–97. It then skips until that time: - `src/lib/scheduler-service.ts`, around lines 811–818: ```ts if (scheduleConfig.nextRun && new Date(scheduleConfig.nextRun) > currentTime) { console.log(`[Scheduler] Skipping user ${config.userId} - next run at ${scheduleConfig.nextRun}`); continue; } ``` Therefore repeated “Skipping user … next run at …” lines mean the scheduler loop is still running; they do not mean it crashed. ### Proposed fix 1. Require an age check for a null checkpoint: ```ts or( and( isNull(mirrorJobs.lastCheckpoint), lt(mirrorJobs.startedAt, cutoffTime), ), lt(mirrorJobs.lastCheckpoint, cutoffTime), lt(mirrorJobs.startedAt, staleCutoffTime), ) ``` 2. Set an initial checkpoint/heartbeat when creating an in-progress job, and refresh it during long-running item processing—not only after item completion. 3. Add an atomic database-backed recovery claim/lease for a job before resuming it. A module-level boolean cannot safely coordinate job ownership or distinguish an active job from an abandoned one. 4. Do not execute full recovery from request middleware. Use a dedicated recovery worker/startup process. If middleware keeps a bounded wait, it must keep the in-flight state tied to the underlying recovery promise until that promise settles. 5. Adjust scheduling so a failed/interrupted scheduled sync is retried appropriately instead of only waiting for the ordinary `nextRun`. ### Impact This can cause duplicate or conflicting mirror/sync activity, misleading recovery logs, and a silent delay in future scheduled work. The UI’s LIVE mode and health checks make it more visible because they generate requests frequently, but they are not the root cause.

adam closed this issue

2026-10-05 01:44:57 +02:00

adam commented

2026-10-05 01:44:58 +02:00

@hunter-nl Thanks for the Bug report and the solution. Please test the latest version and let me know if any issues still there.

@hunter-nl Thanks for the Bug report and the solution. Please test the latest version and let me know if any issues still there.

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: adam/gitea-mirror#150