From 92004ee576dcd7fe6eb98e2bc6802e3ed4516525 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Paul=20L=C3=BCtzner?= Date: Thu, 27 Aug 2026 00:38:16 +0200 Subject: [PATCH] fix(jobs): background work would not open, and finished work never left MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two faults in the same indicator, reported together as "it fades in and out but clicking does nothing" plus three "Marking as read" jobs stuck at partial progress that had stopped weeks earlier. The menu was hidden by Tailwind's `hidden` CLASS while ui--dropdown opens a menu by clearing the `hidden` PROPERTY and never touches classes. So the panel was display:none for the whole life of the page — and because the attribute was absent, the first click read the menu as already open and CLOSED it. No error, no console warning, nothing to search for. Every other dropdown in the app uses the attribute; this was the one that did not, and a static test now says so. The stuck jobs were a different fault with the same face. findVisibleForUser matched `state IN (queued, running)` with no time bound of any kind, so "still going" and "abandoned" were literally the same row and no amount of waiting would ever change it. A job that fails properly calls finish() and clears after five minutes; these never reached that line — a killed worker, a restart mid-deploy, a fatal that bypassed the failure path. The entity had no progress timestamp, so a long legitimate job could not be told from an abandoned one by time. It has one now, stamped by begin() and advance() so the counter and the stamp cannot come apart, the query is bounded by it, and app:jobs:reap marks the stragglers failed so they are seen once and then go. The migration backfills last_progress_at from created_at, which is the only value that gets both directions right: a job stranded weeks ago is instantly outside the window and swept, while a bulk action started two minutes before the deploy is inside it and left alone. Co-Authored-By: Claude Opus 5 --- migrations/Version20260826231407.php | 79 +++++ .../Maintenance/ReapStrandedJobsCommand.php | 238 +++++++++++++++ src/Entity/Job/BackgroundJob.php | 74 ++++- .../Handler/RunBulkStatusHandler.php | 16 +- .../Job/BackgroundJobRepository.php | 79 ++++- templates/mail/_jobs_indicator.html.twig | 12 +- .../ReapStrandedJobsCommandTest.php | 278 ++++++++++++++++++ tests/Entity/Job/BackgroundJobTest.php | 57 ++++ .../DropdownMenusUseHiddenAttributeTest.php | 85 ++++++ .../Job/BackgroundJobVisibilityTest.php | 217 ++++++++++++++ 10 files changed, 1124 insertions(+), 11 deletions(-) create mode 100644 migrations/Version20260826231407.php create mode 100644 src/Command/Maintenance/ReapStrandedJobsCommand.php create mode 100644 tests/Command/Maintenance/ReapStrandedJobsCommandTest.php create mode 100644 tests/Infrastructure/Templating/DropdownMenusUseHiddenAttributeTest.php create mode 100644 tests/Repository/Job/BackgroundJobVisibilityTest.php 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. #}