diff --git a/migrations/Version20260826231407.php b/migrations/Version20260826231407.php new file mode 100644 index 00000000..8faf7768 --- /dev/null +++ b/migrations/Version20260826231407.php @@ -0,0 +1,79 @@ +addSql('ALTER TABLE background_job ADD last_progress_at TIMESTAMP(0) WITHOUT TIME ZONE DEFAULT NULL'); + + // The load-bearing half — see the docblock. Anything that existed before + // this column did last showed a sign of life, at the very latest, when + // it was created. + $this->addSql('UPDATE background_job SET last_progress_at = created_at WHERE last_progress_at IS NULL'); + + $this->addSql('ALTER TABLE background_job ALTER COLUMN last_progress_at SET NOT NULL'); + } + + public function down(Schema $schema): void + { + $this->addSql('ALTER TABLE background_job DROP last_progress_at'); + } +} diff --git a/src/Command/Maintenance/ReapStrandedJobsCommand.php b/src/Command/Maintenance/ReapStrandedJobsCommand.php new file mode 100644 index 00000000..10ea09e7 --- /dev/null +++ b/src/Command/Maintenance/ReapStrandedJobsCommand.php @@ -0,0 +1,238 @@ +addOption( + 'stale-seconds', + null, + InputOption::VALUE_REQUIRED, + 'How long an active job may go without progress before it counts as abandoned', + (string) BackgroundJobRepository::DEFAULT_STALE_SECONDS, + ) + ->addOption('dry-run', null, InputOption::VALUE_NONE, 'List what would be failed without failing it'); + } + + protected function execute(InputInterface $input, OutputInterface $output): int + { + $io = new SymfonyStyle($input, $output); + + if (false === in_array(PHP_SAPI, self::CONSOLE_SAPIS, true)) { + // Refused rather than degraded. This writes to jobs belonging to + // every user on the install and publishes for each one; a web + // process that reached here has been wired up wrongly, and doing + // the work anyway would hide that until it happened once per + // request. See the class docblock. + $io->error(sprintf('app:jobs:reap runs on a worker, not in a web request (SAPI: %s).', PHP_SAPI)); + + return Command::FAILURE; + } + + $seconds = (int) $input->getOption('stale-seconds'); + + if (60 > $seconds) { + // A minute is already shorter than a legitimate chunk over a slow + // IMAP host. Below that this stops being a reaper and becomes a + // race against the work it is meant to be watching. + $io->error('--stale-seconds must be at least 60; anything shorter fails work that is merely between chunks.'); + + return Command::INVALID; + } + + $dryRun = true === $input->getOption('dry-run'); + $before = new DateTimeImmutable(sprintf('-%d seconds', $seconds)); + $stranded = $this->jobs->findStranded($before, self::BATCH); + + if ([] === $stranded) { + $io->success('No stranded background jobs.'); + + return Command::SUCCESS; + } + + if (true === $dryRun) { + foreach ($stranded as $job) { + $io->text(sprintf('would fail %s', $this->describe($job))); + } + + $io->success(sprintf('Would fail %d stranded job(s) (no progress for %ds).', count($stranded), $seconds)); + + return Command::SUCCESS; + } + + foreach ($stranded as $job) { + $this->logger->warning('ReapStrandedJobsCommand: failing a job whose worker stopped reporting', [ + 'jobId' => $job->id, + 'kind' => $job->kind->value, + 'state' => $job->state->value, + 'processed' => $job->processed, + 'total' => $job->total, + 'lastProgressAt' => $job->lastProgressAt->format(DATE_ATOM), + ]); + + $job->finish(JobState::Failed, $this->reasonFor($job)); + } + + // ONE flush for the batch. Each finish() writes three scalars on a row + // this command already holds, so there is no per-job failure mode to + // isolate — a flush that cannot write one of them cannot write any of + // them, and a half-swept table would be worse than an unswept one. + $this->em->flush(); + + // Published only after the write has landed. JobNotifier carries no + // state — it says "look again" — so a page nudged before the commit + // would re-read the row it already had and stay wrong until something + // else happened to it. + foreach ($stranded as $job) { + $this->notifier->changed($job); + } + + $io->success(sprintf('Failed %d stranded job(s) (no progress for %ds).', count($stranded), $seconds)); + + return Command::SUCCESS; + } + + // ── Private ─────────────────────────────────────────────────────────────── + + /** + * The stored reason, translated into the OWNER's language rather than the + * console's. + * + * Translated here and stored as text, not stored as a key: failureReason + * holds a provider's own words for every other failure and the indicator + * renders it raw, so making this one a key would leave the template holding + * a column that is sometimes a key and sometimes prose, with no way to tell + * which. The cost is that a user who later switches language keeps this one + * sentence in the old one — for five minutes, until the failure window + * closes over it. App\Service\Calendar\CalendarProvisioner stores a + * user-locale string the same way and for the same reason. + */ + private function reasonFor(BackgroundJob $job): string + { + return $this->translator->trans(self::REASON_KEY, [], null, $job->usr->locale); + } + + private function describe(BackgroundJob $job): string + { + return sprintf( + 'job %d (%s, %s, %d/%d), last moved %s', + (int) $job->id, + $job->kind->value, + $job->state->value, + $job->processed, + $job->total, + $job->lastProgressAt->format(DATE_ATOM), + ); + } +} diff --git a/src/Entity/Job/BackgroundJob.php b/src/Entity/Job/BackgroundJob.php index ad082dd6..d3bdfe3a 100644 --- a/src/Entity/Job/BackgroundJob.php +++ b/src/Entity/Job/BackgroundJob.php @@ -71,6 +71,36 @@ class BackgroundJob #[ORM\Column] public DateTimeImmutable $createdAt; + /** + * When this job last showed a sign of life. + * + * WHY A SECOND TIMESTAMP HAD TO EXIST + * + * createdAt and finishedAt together cannot tell an ABANDONED job from a + * slow one. A worker killed mid-run — a container restarted during a + * deploy, an OOM kill, a fatal that never reaches finish() — leaves the row + * in `running` with no finishedAt, which is character for character what a + * job still grinding through a large mailbox looks like. + * + * That is not hypothetical: three "Marking as read" jobs sat in the topbar + * indicator at 1400/1770, 600/1180 and 100/1275 for weeks. The query behind + * the indicator had no time bound on its active arm at all, so a stranded + * job was visible FOREVER and nothing in the application could ever have + * cleared it — there was no fact on the row to clear it by. + * + * This column is that fact. It moves on every chunk (see advance()), so a + * job legitimately working through fifty thousand conversations is never + * mistaken for a dead one however long it takes, while a job whose worker + * is gone stops moving at the same moment the worker does. + * + * NOT NULLABLE, and stamped in the constructor. A queued job no worker has + * picked up yet is alive and should be shown; a null here would have to be + * read as either "brand new" or "long dead" by every caller, and the two + * want opposite answers. + */ + #[ORM\Column] + public DateTimeImmutable $lastProgressAt; + #[ORM\Column(nullable: true)] public ?DateTimeImmutable $finishedAt = null; @@ -98,9 +128,16 @@ class BackgroundJob public function __construct(User $usr, JobKind $kind) { - $this->usr = $usr; - $this->kind = $kind; - $this->createdAt = new DateTimeImmutable(); + // One instant read once and used twice, rather than two calls. A job + // created across a second boundary would otherwise be born with a + // progress stamp older than itself, which is indistinguishable from a + // job that has already been sitting still. + $now = new DateTimeImmutable(); + + $this->usr = $usr; + $this->kind = $kind; + $this->createdAt = $now; + $this->lastProgressAt = $now; } /** Whole percent, floored, and never a lie: 0 until there is a total. */ @@ -118,6 +155,37 @@ class BackgroundJob return $this->state->isActive(); } + /** + * The work has been planned: this is how much of it there is. + * + * Stamps lastProgressAt as well as writing the total, because resolving a + * whole view into threads is itself minutes of work on a large mailbox — + * and a reaper that did not count that as progress would fail a job for the + * time it spent working out what the job was. + */ + public function begin(int $total): void + { + $this->state = JobState::Running; + $this->total = $total; + $this->lastProgressAt = new DateTimeImmutable(); + } + + /** + * Another chunk is through. + * + * The stamp lives HERE rather than at the call site so that "the counter + * moved" and "the job is alive" cannot come apart. A handler that wrote + * the counter and forgot the timestamp would have its jobs reaped mid-run, + * and the only symptom would be work failing after exactly the staleness + * window, every time, with a progress bar that had been moving right up to + * the moment it was told it had died. + */ + public function advance(int $processed): void + { + $this->processed = $processed; + $this->lastProgressAt = new DateTimeImmutable(); + } + public function finish(JobState $state, ?string $reason = null): void { $this->state = $state; diff --git a/src/Infrastructure/Messaging/Handler/RunBulkStatusHandler.php b/src/Infrastructure/Messaging/Handler/RunBulkStatusHandler.php index 163b0024..433226f6 100644 --- a/src/Infrastructure/Messaging/Handler/RunBulkStatusHandler.php +++ b/src/Infrastructure/Messaging/Handler/RunBulkStatusHandler.php @@ -124,8 +124,12 @@ final readonly class RunBulkStatusHandler true === $job->view['unreadOnly'], ); - $job->state = JobState::Running; - $job->total = count($threads); + // begin() stamps lastProgressAt along with the total, and that stamp is + // the point: resolving a whole view into threads is itself minutes of + // work on a large mailbox, so without it a job would arrive here + // already looking older than the staleness window and app:jobs:reap + // would fail it for the time it spent working out what it was. + $job->begin(count($threads)); $this->em->flush(); $this->notifier->changed($job); @@ -171,7 +175,13 @@ final readonly class RunBulkStatusHandler // Assigned rather than incremented, because $processed is counted // here and the row is re-read each time: += against a fresh read // would be adding this run's total to itself. - $fresh->processed = $processed; + // + // Through advance() rather than by writing the counter, so the + // progress stamp moves with it. That stamp is the ONLY evidence + // this job is alive: app:jobs:reap reads it, and a chunk that + // updated the number without it would be a job quietly reaped while + // it was still working. + $fresh->advance($processed); $this->em->flush(); $this->notifier->changed($fresh); } diff --git a/src/Repository/Job/BackgroundJobRepository.php b/src/Repository/Job/BackgroundJobRepository.php index 8590fed5..9a1c3aaa 100644 --- a/src/Repository/Job/BackgroundJobRepository.php +++ b/src/Repository/Job/BackgroundJobRepository.php @@ -16,13 +16,31 @@ use Symfony\Component\Security\Core\User\UserInterface; */ class BackgroundJobRepository extends ServiceEntityRepository { + /** + * How long an active job may go without moving before it counts as + * abandoned rather than slow, in seconds. + * + * Fifteen minutes, and generous deliberately. A chunk is a hundred + * conversations and each of them can carry a provider round trip, so a slow + * IMAP host makes an entirely healthy chunk take minutes. The two ways to + * be wrong here are not symmetrical: too long and a dead job lingers in the + * indicator for another quarter of an hour, too short and live work is + * declared failed while it is still running — and the user is told nothing + * happened when in fact it did. + * + * SECONDS, like the failure window beside it in findVisibleForUser. One + * class measuring two windows in two units is how a sixty-times mistake + * gets made. + */ + public const int DEFAULT_STALE_SECONDS = 900; + public function __construct(ManagerRegistry $registry) { parent::__construct($registry, BackgroundJob::class); } /** - * This user's jobs worth showing: everything still going, plus anything + * This user's jobs worth showing: everything still MOVING, plus anything * that FAILED recently. * * Success does not linger, and that is deliberate. A finished mark-as-read @@ -35,16 +53,40 @@ class BackgroundJobRepository extends ServiceEntityRepository * A failure is the opposite: nothing changed, and if this does not say so * nothing does. So it stays long enough to be read. * + * WHY THE ACTIVE ARM IS BOUNDED BY TIME AT ALL + * + * It was not, and a job in `running` was therefore visible forever. Three + * "Marking as read" jobs stopped at 1400/1770, 600/1180 and 100/1275 — + * workers killed mid-flight, so finish() was never reached and no state on + * the row ever changed again — and the indicator went on reporting them as + * running for weeks. There was nothing the user could press, and nothing + * the application could have done about it either: "still going" and + * "abandoned" were the same row. + * + * lastProgressAt is what separates them, and this is where the separation + * has to happen. The reaper (app:jobs:reap) turns such a job into a real + * failure so the user is told once, but the reaper runs every few minutes + * while a page renders now — so the read has to be able to answer correctly + * on its own, before anything has been swept. + * + * The two windows are different things and are passed separately: the + * failure window is how long a person gets to READ bad news, the staleness + * window is how long a worker may go quiet before we stop believing it. + * * @return list */ - public function findVisibleForUser(UserInterface $user, int $failureWindowSeconds = 300): array - { + public function findVisibleForUser( + UserInterface $user, + int $failureWindowSeconds = 300, + int $staleAfterSeconds = self::DEFAULT_STALE_SECONDS, + ): array { return $this->createQueryBuilder('job') ->where('job.usr = :user') - ->andWhere('job.state IN (:active) OR (job.state = :failed AND job.finishedAt > :since)') + ->andWhere('(job.state IN (:active) AND job.lastProgressAt > :moving) OR (job.state = :failed AND job.finishedAt > :since)') ->setParameter('user', $user) ->setParameter('active', [JobState::Queued, JobState::Running]) ->setParameter('failed', JobState::Failed) + ->setParameter('moving', new DateTimeImmutable(sprintf('-%d seconds', $staleAfterSeconds))) ->setParameter('since', new DateTimeImmutable(sprintf('-%d seconds', $failureWindowSeconds))) ->orderBy('job.createdAt', 'DESC') ->setMaxResults(20) @@ -52,6 +94,35 @@ class BackgroundJobRepository extends ServiceEntityRepository ->getResult(); } + /** + * Jobs that claim to be active and have stopped moving — across every user. + * + * The exact complement of the active arm above: that one keeps rows whose + * stamp is strictly NEWER than the cutoff, this one takes the rest. Written + * as `<=` against the same instant on purpose, so a job cannot fall through + * the gap between the two and be neither shown nor swept. + * + * Not scoped to a user, because nobody asks this question on a user's + * behalf — app:jobs:reap sweeps the table, and the mess it cleans up was + * made by a worker dying, which is not a per-user event. + * + * @return list + */ + public function findStranded(DateTimeImmutable $before, int $limit = 200): array + { + return $this->createQueryBuilder('job') + ->where('job.state IN (:active)') + ->andWhere('job.lastProgressAt <= :before') + ->setParameter('active', [JobState::Queued, JobState::Running]) + ->setParameter('before', $before) + // Oldest first, so a capped run always retires the jobs that have + // been misleading somebody the longest. + ->orderBy('job.lastProgressAt', 'ASC') + ->setMaxResults($limit) + ->getQuery() + ->getResult(); + } + /** * Jobs old enough that nobody is waiting on them. * diff --git a/templates/mail/_jobs_indicator.html.twig b/templates/mail/_jobs_indicator.html.twig index e26bd5bb..78007d92 100644 --- a/templates/mail/_jobs_indicator.html.twig +++ b/templates/mail/_jobs_indicator.html.twig @@ -52,10 +52,20 @@ the record and a missed nudge costs one stale render, never a wrong answer. aria-hidden="true"> + {# The `hidden` ATTRIBUTE, not the Tailwind class. + ui--dropdown opens a menu by clearing `hidden` as a property, and + it never touches classes. With the class instead, the panel was + display:none no matter what the controller did — and because the + attribute was absent, the FIRST click read the menu as already + open and closed it. So the button pulsed away saying work was + running, and clicking it did nothing at all, for ever. Every + other dropdown in the app uses the attribute; this was the one + that did not. #}