jody/pl_mail
1
0 Fork 0
mirror of https://github.com/karatektus/pl_mail.git synced 2026-10-25 01:54:10 +00:00
Code Issues Packages Projects Releases Wiki Activity

fix(jobs): background work would not open, and finished work never left

Browse Source 
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 <noreply@anthropic.com>
This commit is contained in:
Paul LütznerandClaude Opus 5 committed 2026-08-27 00:38:16 +02:00
1 parent 6c33316f33
commit 92004ee576
10 files changed
+1124 -11
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

migrations/Version20260826231407.php
+79
View File
@@ -0,0 +1,79 @@
<?php
declare(strict_types=1);
namespace DoctrineMigrations;
use Doctrine\DBAL\Schema\Schema;
use Doctrine\Migrations\AbstractMigration;
/**
* Gives a background job a heartbeat, so an abandoned one can be told from a
* slow one.
*
* `background_job` carried created_at and finished_at and nothing in between,
* which meant a worker killed mid-run — a container restarted during a deploy,
* an OOM kill, a fatal that never reached finish() — left a row in `running`
* that was byte for byte identical to a job still working. The indicator query
* had no time bound on its active arm, so three "Marking as read" jobs sat in
* one user's topbar at 1400/1770, 600/1180 and 100/1275 for weeks, with nothing
* on the row that could ever have cleared them.
*
* THE BACKFILL IS THE POINT OF THIS MIGRATION, not the column.
*
* Added nullable, backfilled, then made NOT NULL — the sequence CODESTYLE
* requires, because a NOT NULL column with no default cannot be added to a
* table that already has rows, and this one always does on precisely the
* installs that have the bug.
*
* The backfilled value is `created_at`, and the choice is load-bearing in both
* directions:
*
* - Leaving it NULL, or stamping NOW(), makes every pre-existing row look
* freshly alive. The three stranded jobs would survive the deploy that was
* meant to be rid of them and stay on screen for ever, which is the entire
* reported symptom.
* - Stamping a fixed instant in the past — or, equivalently, teaching the
* query to read NULL as "long dead" — condemns every row, including a bulk
* action a user started two minutes before the deploy and is watching right
* now. It would be reported as failed while its worker was still marking
* mail read, and the user would be told nothing happened when it had.
*
* created_at gets both right, because it is the one thing already known about
* the row that correlates with whether anybody is still waiting on it. A job
* stranded weeks ago is instantly older than the fifteen-minute staleness
* window and is swept on the next run of app:jobs:reap; a job started moments
* ago is inside that window and is left alone until its own next chunk stamps
* the column properly. The worst case is a genuinely long-running job in flight
* across the deploy: it reads as stale until its next chunk lands, which is
* seconds to minutes away, and that chunk puts it back on screen.
*
* No default is left behind on the column. Every row is written through
* App\Entity\Job\BackgroundJob, whose constructor stamps it from the same
* instant as created_at; a lingering DEFAULT NOW() would exist only to rescue a
* writer that must not exist.
*/
final class Version20260826231407 extends AbstractMigration
{
public function getDescription(): string
{
return 'Add background_job.last_progress_at and backfill it from created_at so stranded jobs read as stale';
}
public function up(Schema $schema): void
{
$this->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');
}
}
src/Command/Maintenance/ReapStrandedJobsCommand.php
+238
View File
@@ -0,0 +1,238 @@
<?php
declare(strict_types=1);
namespace App\Command\Maintenance;
use App\Domain\Enum\Job\JobState;
use App\Entity\Job\BackgroundJob;
use App\Repository\Job\BackgroundJobRepository;
use App\Service\Job\JobNotifier;
use DateTimeImmutable;
use Doctrine\ORM\EntityManagerInterface;
use Psr\Log\LoggerInterface;
use Symfony\Component\Console\Attribute\AsCommand;
use Symfony\Component\Console\Command\Command;
use Symfony\Component\Console\Input\InputInterface;
use Symfony\Component\Console\Input\InputOption;
use Symfony\Component\Console\Output\OutputInterface;
use Symfony\Component\Console\Style\SymfonyStyle;
use Symfony\Contracts\Translation\TranslatorInterface;
/**
* Fails background jobs whose worker is never coming back.
*
* THE BUG THIS CLOSES
*
* A user reported three "Marking as read" jobs pinned in the topbar indicator
* at 1400/1770, 600/1180 and 100/1275. They had finished — or rather stopped —
* long before, and there was no way on earth to be rid of them. Each was a row
* left in `running` by a worker that died mid-flight: a container restarted
* during a deploy, an OOM kill, a fatal that never reached
* RunBulkStatusHandler's failure path. Nothing else was ever going to touch
* those rows, because the only code that writes them is the handler that is no
* longer running.
*
* BackgroundJob::$lastProgressAt made the state readable and
* BackgroundJobRepository::findVisibleForUser stopped SHOWING such a job. This
* is the other half: without it those rows would merely become invisible, which
* is a quieter version of the same lie — the user asked for five thousand
* conversations to be marked read, about fourteen hundred of them were, and
* nothing would ever have said so.
*
* WHY FAILED AND NOT DONE, AND NOT DELETED
*
* Failed is the truth. The work stopped part-way, the mailbox is in a state
* nobody asked for, and JobState exists to distinguish exactly that from a
* clean finish. Marking it done would tell the user their mail was handled;
* deleting the row would tell them nothing at all, which is what has been
* happening. Failed also puts the row into the failure window
* findVisibleForUser already implements, so the indicator shows it once, for
* five minutes, and then clears itself — a thing that appears, says what
* happened, and goes away, rather than another permanent fixture.
*
* WHY A COMMAND AND NOT A SWEEP ON READ
*
* The tempting shortcut is to retire stale jobs while rendering the indicator,
* since that is the code that notices them. It would put a write and a Mercure
* publish inside a GET that every page load makes, for every user, to answer
* "nothing is happening" almost every time — and it would run that write
* concurrently in as many web processes as there are open tabs. See
* App\Twig\BackgroundJobsExtension for how hard that path has already been
* fought over. This runs on the maintenance worker, once, on a schedule; the
* read path stays a read.
*
* Idempotent by construction: finish() takes the job out of Queued/Running, so
* the query that found it cannot find it again. Safe to run by hand next to the
* scheduled run, and safe to run twice.
*/
#[AsCommand(
name: 'app:jobs:reap',
description: 'Fail background jobs that stopped reporting progress, so the indicator stops claiming they are running',
)]
final class ReapStrandedJobsCommand extends Command
{
/**
* What the user is told, in their own language.
*
* A short category rather than a message about workers and containers: the
* person reading it started a bulk action and needs to know it did not
* finish, not how plMail is deployed.
*/
private const string REASON_KEY = 'jobs.failure.abandoned';
/**
* Per run. Generous — a table with two hundred stranded jobs in it has a
* problem this command is not the answer to — but bounded all the same, so
* one pathological backlog cannot hold the maintenance worker while
* snoozes and calendar alerts queue up behind it.
*/
private const int BATCH = 200;
/**
* The SAPIs this is allowed to run under.
*
* Denied rather than listing the ones that serve HTTP, the way
* App\Service\Monitoring\WebProcessRestart spells the same list: a runtime
* nobody here has heard of should default to "not this process", never to
* "probably fine, write to every user's jobs".
*/
private const array CONSOLE_SAPIS = ['cli', 'phpdbg', 'embed'];
public function __construct(
private readonly BackgroundJobRepository $jobs,
private readonly JobNotifier $notifier,
private readonly TranslatorInterface $translator,
private readonly EntityManagerInterface $em,
private readonly LoggerInterface $logger,
) {
parent::__construct();
}
protected function configure(): void
{
$this
// Seconds, matching BackgroundJobRepository, which measures the
// failure window in seconds beside it. Two units in one feature is
// how somebody eventually reaps after fifteen SECONDS.
->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),
);
}
}
src/Entity/Job/BackgroundJob.php
+71 -3
View File
@@ -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;
src/Infrastructure/Messaging/Handler/RunBulkStatusHandler.php
+13 -3
View File
@@ -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);
}
src/Repository/Job/BackgroundJobRepository.php
+75 -4
View File
@@ -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<BackgroundJob>
*/
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<BackgroundJob>
*/
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.
*
templates/mail/_jobs_indicator.html.twig
+11 -1
View File
@@ -52,10 +52,20 @@ the record and a missed nudge costs one stale render, never a wrong answer.
aria-hidden="true"></i>
</button>
{# 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. #}
<div
data-ui--dropdown-target="menu"
data-enter="slide-down"
class="hidden absolute right-0 top-full mt-1 z-30 w-80
hidden
class="absolute right-0 top-full mt-1 z-30 w-80
rounded-pane bg-pane-soft backdrop-blur-sm
border border-line shadow-pop p-2 text-sm"
>
tests/Command/Maintenance/ReapStrandedJobsCommandTest.php
+278
View File
@@ -0,0 +1,278 @@
<?php
declare(strict_types=1);
namespace App\Tests\Command\Maintenance;
use App\Domain\Enum\Job\JobKind;
use App\Domain\Enum\Job\JobState;
use App\Entity\Job\BackgroundJob;
use App\Entity\User\User;
use App\Repository\Job\BackgroundJobRepository;
use DateTimeImmutable;
use Doctrine\DBAL\Connection;
use Doctrine\ORM\EntityManagerInterface;
use Symfony\Bundle\FrameworkBundle\Console\Application;
use Symfony\Bundle\FrameworkBundle\Test\KernelTestCase;
use Symfony\Component\Console\Command\Command;
use Symfony\Component\Console\Tester\CommandTester;
use Symfony\Contracts\Translation\TranslatorInterface;
/**
* The half of the fix that actually TELLS somebody.
*
* Bounding the indicator's query stopped three dead "Marking as read" jobs
* being reported as running, but on its own that only makes them invisible —
* and the user did ask for five thousand conversations to be marked read, about
* fourteen hundred of them were, and silence about that is a quieter version of
* the same lie. This command turns each stranded row into a real failure, which
* the indicator already knows how to show once and then forget.
*
* Two properties are worth more than the rest here:
*
* - **Idempotence.** finish() takes the row out of Queued/Running, so the
* query that found it cannot find it again. The scheduler replays a missed
* run and an operator will run this by hand next to a scheduled one; a
* second pass must not restamp finishedAt and slide the failure window
* forward, because a failure that keeps renewing itself is the permanent
* topbar fixture this whole change exists to remove.
* - **It leaves live work alone.** The expensive mistake is not a stranded
* job surviving another five minutes; it is failing a bulk action that was
* going to finish, and telling the user nothing happened when it did.
*/
final class ReapStrandedJobsCommandTest extends KernelTestCase
{
/** Comfortably past the fifteen-minute default, and obviously so when a test fails. */
private const string LONG_DEAD = '-2 hours';
private EntityManagerInterface $em;
private Connection $connection;
private BackgroundJobRepository $repository;
private TranslatorInterface $translator;
private CommandTester $command;
private User $user;
protected function setUp(): void
{
self::bootKernel();
$container = self::getContainer();
$this->em = $container->get(EntityManagerInterface::class);
$this->connection = $container->get(Connection::class);
$this->repository = $container->get(BackgroundJobRepository::class);
$this->translator = $container->get(TranslatorInterface::class);
$this->connection->beginTransaction();
// THE TABLE IS THE FIXTURE HERE, so the table has to be emptied first.
// app:jobs:reap sweeps every user's jobs by design, and background_job
// is shared with whatever else the suite has run —
// BulkStatusOffloadTest is a WebTestCase and COMMITS the jobs it
// creates, which then go stale between runs of the suite. Without this
// the counts below would be right on a fresh database and wrong on the
// second afternoon. Transactional in Postgres, so the rollback in
// tearDown puts them back.
$this->connection->executeStatement('DELETE FROM background_job');
$this->user = $this->seedUser();
$this->command = new CommandTester(
new Application(self::$kernel)->find('app:jobs:reap'),
);
}
protected function tearDown(): void
{
if (true === $this->connection->isTransactionActive()) {
$this->connection->rollBack();
}
parent::tearDown();
}
/**
* The reported row, and what the user should have been told about it weeks
* ago.
*/
public function testAStrandedJobIsFailedWithAReasonThePersonCanRead(): void
{
$job = $this->job(JobState::Running, self::LONG_DEAD);
$this->command->execute([]);
self::assertSame(Command::SUCCESS, $this->command->getStatusCode());
self::assertStringContainsString('Failed 1', $this->command->getDisplay());
$this->em->refresh($job);
self::assertSame(JobState::Failed, $job->state);
self::assertNotNull($job->finishedAt);
// A translated category, not a raw key and not a stack trace. The
// template renders this straight into the indicator, so anything that
// leaks through appears verbatim in front of somebody.
self::assertSame($this->translator->trans('jobs.failure.abandoned', [], null, $this->user->locale), $job->failureReason);
self::assertStringNotContainsString('jobs.failure', (string) $job->failureReason);
}
/**
* And the failure is then visible — once, through the window that already
* exists.
*
* This is the property the whole change is for: the indicator that had been
* lying goes quiet, says what actually happened, and clears itself, rather
* than either lying forever or falling silent without explanation.
*/
public function testTheFailureIsWhatTheIndicatorThenShows(): void
{
$this->job(JobState::Running, self::LONG_DEAD);
$beforeSweep = $this->visibleStates();
self::assertSame([], $beforeSweep, 'a stranded job is not reported as running');
$this->command->execute([]);
$afterSweep = $this->visibleStates();
self::assertSame(['failed'], $afterSweep, 'and the sweep is what puts it back on screen, as a failure');
}
/**
* A job whose worker flushed a chunk a moment ago is working, however long
* it has been running.
*/
public function testAJobStillReportingProgressIsLeftAlone(): void
{
$job = $this->job(JobState::Running, '-30 seconds', createdAt: '-3 hours');
$this->command->execute([]);
self::assertStringContainsString('No stranded background jobs.', $this->command->getDisplay());
$this->em->refresh($job);
self::assertSame(JobState::Running, $job->state);
self::assertNull($job->finishedAt);
}
/**
* Running it again finds nothing and, above all, does not restamp the
* failure.
*
* The scheduler replays a missed run and an operator will run this by hand;
* a second pass that moved finishedAt forward would push the five-minute
* failure window along with it, and the indicator would never clear.
*/
public function testRunningItAgainReapsNothingAndDoesNotMoveTheFailureWindow(): void
{
$job = $this->job(JobState::Running, self::LONG_DEAD);
$this->command->execute([]);
$this->em->refresh($job);
$finishedAt = $job->finishedAt;
$this->command->execute([]);
self::assertSame(Command::SUCCESS, $this->command->getStatusCode());
self::assertStringContainsString('No stranded background jobs.', $this->command->getDisplay());
$this->em->refresh($job);
self::assertEquals($finishedAt, $job->finishedAt, 'a second sweep must not renew a failure it did not cause');
self::assertSame(JobState::Failed, $job->state);
}
/** A dry run says what it would do and writes nothing, like every other sweep here. */
public function testADryRunChangesNothing(): void
{
$job = $this->job(JobState::Running, self::LONG_DEAD);
$this->command->execute(['--dry-run' => true]);
self::assertStringContainsString('Would fail 1', $this->command->getDisplay());
$this->em->refresh($job);
self::assertSame(JobState::Running, $job->state);
self::assertNull($job->finishedAt);
}
/**
* A window short enough to race the work it is watching is refused.
*
* A chunk is a hundred conversations and each can carry a provider round
* trip, so seconds-scale staleness would fail healthy jobs mid-run — and
* the operator who typed it would read the resulting failures as evidence
* that the queue is broken.
*/
public function testAnAbsurdlyShortWindowIsRefusedRatherThanObeyed(): void
{
$job = $this->job(JobState::Running, '-30 seconds');
$this->command->execute(['--stale-seconds' => '5']);
self::assertSame(Command::INVALID, $this->command->getStatusCode());
$this->em->refresh($job);
self::assertSame(JobState::Running, $job->state);
}
// ── Private ───────────────────────────────────────────────────────────────
/**
* What the topbar indicator would render for this user, as plain strings.
*
* States rather than entities, because the claim is about what a person
* sees. Read into a variable by every caller before asserting: two
* assertions against the same call expression let static analysis conclude
* the second one is unreachable.
*
* @return list<string>
*/
private function visibleStates(): array
{
return array_map(
static fn (BackgroundJob $job): string => $job->state->value,
$this->repository->findVisibleForUser($this->user),
);
}
private function job(
JobState $state,
string $lastProgressAt,
?string $createdAt = null,
): BackgroundJob {
$job = new BackgroundJob($this->user, JobKind::MarkRead);
$job->state = $state;
$job->total = 1770;
$job->processed = 1400;
$job->lastProgressAt = new DateTimeImmutable($lastProgressAt);
$job->createdAt = new DateTimeImmutable($createdAt ?? $lastProgressAt);
$this->em->persist($job);
$this->em->flush();
return $job;
}
private function seedUser(): User
{
$user = new User();
$user->email = 'reap-' . uniqid('', true) . '@example.test';
$user->nameFirst = 'Reap';
$user->nameLast = 'Fixture';
$user->roles = ['ROLE_USER'];
$user->password = 'x';
$this->em->persist($user);
$this->em->flush();
return $user;
}
}
tests/Entity/Job/BackgroundJobTest.php
+57
View File
@@ -8,6 +8,7 @@ use App\Domain\Enum\Job\JobKind;
use App\Domain\Enum\Job\JobState;
use App\Entity\Job\BackgroundJob;
use App\Entity\User\User;
use DateTimeImmutable;
use PHPUnit\Framework\TestCase;
/**
@@ -77,6 +78,62 @@ final class BackgroundJobTest extends TestCase
self::assertNull($job->failureReason, 'a completed job must not keep an old failure');
}
/**
* A job is born looking alive, which is what makes a QUEUED job visible.
*
* The staleness bound in BackgroundJobRepository::findVisibleForUser reads
* lastProgressAt and nothing else, so a job that arrived at the stamp some
* other way — a second `new DateTimeImmutable()` across a second boundary,
* a null left for the reader to interpret — is a job that flickers out of
* the indicator between being started and being picked up.
*/
public function testAJobIsBornWithAProgressStampMatchingItsCreation(): void
{
$job = $this->job();
self::assertEquals($job->createdAt, $job->lastProgressAt);
}
/**
* Planning the work counts as progress.
*
* Resolving a whole view into threads takes minutes on a large mailbox, and
* it happens before the first chunk. Without a stamp here the job's only
* evidence of life would be its creation, and app:jobs:reap would fail it
* for the time it spent working out what it was.
*/
public function testPlanningTheWorkCountsAsProgress(): void
{
$job = $this->job();
$job->lastProgressAt = new DateTimeImmutable('-1 hour');
$job->begin(1770);
self::assertSame(JobState::Running, $job->state);
self::assertSame(1770, $job->total);
self::assertGreaterThan(new DateTimeImmutable('-1 minute'), $job->lastProgressAt);
}
/**
* A chunk landing moves the STAMP, not only the counter.
*
* The two must not come apart, and this is the test that says so. A handler
* that wrote `processed` directly would leave a job whose progress bar was
* visibly moving right up to the moment the reaper declared it dead — every
* time, after exactly the staleness window, which is the sort of symptom
* that gets blamed on the queue.
*/
public function testAChunkLandingMovesTheProgressStamp(): void
{
$job = $this->job();
$job->lastProgressAt = new DateTimeImmutable('-1 hour');
$job->advance(1400);
self::assertSame(1400, $job->processed);
self::assertGreaterThan(new DateTimeImmutable('-1 minute'), $job->lastProgressAt);
}
/** Marking read and unread are one action with a flag, as the controller has it. */
public function testTheTwoMarkKindsShareAnActionAndDifferInTheFlag(): void
{
tests/Infrastructure/Templating/DropdownMenusUseHiddenAttributeTest.php
+85
View File
@@ -0,0 +1,85 @@
<?php
declare(strict_types=1);
namespace App\Tests\Infrastructure\Templating;
use PHPUnit\Framework\TestCase;
use RecursiveDirectoryIterator;
use RecursiveIteratorIterator;
use SplFileInfo;
/**
* Every ui--dropdown menu is hidden by the ATTRIBUTE, never by the class.
*
* The controller opens a menu with `this.menuTarget.hidden = false` and never
* touches classList. So a menu carrying Tailwind's `hidden` class is
* display:none for the whole life of the page no matter what the controller
* does — and because `hidden` as a property is then false, the first click
* reads the menu as already open and CLOSES it.
*
* The background-work indicator shipped that way. The button pulsed in the
* topbar saying work was running, which was true, and clicking it did nothing
* whatsoever — no error, no console warning, nothing to search for. It is
* invisible to csp.spec.ts and to any test that does not click that exact
* button while a job happens to be running, which is a narrow window to catch
* by luck.
*
* Static, for the same reason NoInlineEventHandlersTest is: the failure needs
* a specific widget in a specific state to show itself, and the mistake is one
* word in a class list that reviews slide past.
*/
final class DropdownMenusUseHiddenAttributeTest extends TestCase
{
public function testNoDropdownMenuIsHiddenByClass(): void
{
$offenders = [];
foreach ($this->templates() as $file) {
$markup = (string) file_get_contents($file->getPathname());
// Each element that declares itself a dropdown menu, with the rest
// of that opening tag — which is where its class list lives.
preg_match_all('/<[^>]*data-ui--dropdown-target="menu"[^>]*>/s', $markup, $matches);
foreach ($matches[0] as $tag) {
if (1 !== preg_match('/\bclass="([^"]*)"/s', $tag, $class)) {
continue;
}
// `hidden` as a whole word in the class list. Not `hidden-foo`,
// and not `md:hidden`, which is a real responsive utility and
// says nothing about the menu's open state.
if (1 === preg_match('/(^|\s)hidden(\s|$)/', $class[1])) {
$offenders[] = $file->getPathname();
}
}
}
self::assertSame(
[],
$offenders,
"A ui--dropdown menu is hidden by the `hidden` CLASS in:\n "
. implode("\n ", array_unique($offenders))
. "\nUse the `hidden` ATTRIBUTE instead — the controller toggles the property.",
);
}
private function templates(): iterable
{
$iterator = new RecursiveIteratorIterator(
new RecursiveDirectoryIterator(self::projectDir() . '/templates'),
);
foreach ($iterator as $file) {
if ($file instanceof SplFileInfo && 'twig' === $file->getExtension()) {
yield $file;
}
}
}
private static function projectDir(): string
{
return \dirname(__DIR__, 3);
}
}
tests/Repository/Job/BackgroundJobVisibilityTest.php
+217
View File
@@ -0,0 +1,217 @@
<?php
declare(strict_types=1);
namespace App\Tests\Repository\Job;
use App\Domain\Enum\Job\JobKind;
use App\Domain\Enum\Job\JobState;
use App\Entity\Job\BackgroundJob;
use App\Entity\User\User;
use App\Repository\Job\BackgroundJobRepository;
use DateTimeImmutable;
use Doctrine\DBAL\Connection;
use Doctrine\ORM\EntityManagerInterface;
use Symfony\Bundle\FrameworkBundle\Test\KernelTestCase;
/**
* What the topbar indicator is allowed to claim is still happening.
*
* The reported bug was three "Marking as read" jobs stuck at 1400/1770,
* 600/1180 and 100/1275 that had stopped weeks earlier. Every one of them was a
* row a killed worker left in `running`, and the query behind the indicator
* 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 or reloading was ever going to change that.
*
* These tests pin the line that now separates them, from both sides. The pair
* that matters is testAJobStillReportingProgressIsShown and
* testAJobWhoseWorkerDiedDropsOut: they differ in ONE column and in nothing
* else, which is the whole claim.
*
* The last test pins the two queries against each other. The indicator keeps
* what is strictly newer than the cutoff and findStranded() takes the rest, so
* a job that fell through the gap between them would be neither shown to
* anybody nor swept by anything — invisible and immortal, which is a worse
* version of the bug rather than a fix for it.
*/
final class BackgroundJobVisibilityTest extends KernelTestCase
{
/** Comfortably outside the fifteen-minute default, and obviously so when a test fails. */
private const string LONG_DEAD = '-2 hours';
private EntityManagerInterface $em;
private Connection $connection;
private BackgroundJobRepository $repository;
private User $user;
protected function setUp(): void
{
self::bootKernel();
$container = self::getContainer();
$this->em = $container->get(EntityManagerInterface::class);
$this->connection = $container->get(Connection::class);
$this->repository = $container->get(BackgroundJobRepository::class);
$this->connection->beginTransaction();
// THE TABLE IS THE FIXTURE HERE, so the table has to be emptied first.
// app:jobs:reap sweeps every user's jobs by design, and background_job
// is shared with whatever else the suite has run —
// BulkStatusOffloadTest is a WebTestCase and COMMITS the jobs it
// creates, which then go stale between runs of the suite. Without this
// the counts below would be right on a fresh database and wrong on the
// second afternoon. Transactional in Postgres, so the rollback in
// tearDown puts them back.
$this->connection->executeStatement('DELETE FROM background_job');
$this->user = $this->seedUser();
}
protected function tearDown(): void
{
if (true === $this->connection->isTransactionActive()) {
$this->connection->rollBack();
}
parent::tearDown();
}
/** A worker that flushed a chunk a moment ago is working, however long it has been at it. */
public function testAJobStillReportingProgressIsShown(): void
{
// Created hours ago on purpose: a bound on createdAt would pass every
// other test in this file and fail this one, and a bulk action over a
// large mailbox genuinely does run for hours.
$job = $this->job(JobState::Running, '-30 seconds', createdAt: '-3 hours');
self::assertSame([$job->id], $this->visibleIds());
}
/** And the same row, differing only in when it last moved, is not. */
public function testAJobWhoseWorkerDiedDropsOut(): void
{
$this->job(JobState::Running, self::LONG_DEAD, createdAt: '-3 hours');
self::assertSame([], $this->visibleIds(), 'a job nothing is working on must stop reporting itself as running');
}
/**
* A job nothing has picked up yet is alive, not stale.
*
* The gap between queued and running is minutes on a busy worker — JobState
* says so in as many words — and the constructor's stamp is what carries a
* job across it. Read a missing or backdated stamp as "dead" and every bulk
* action would vanish from the indicator the instant it was started.
*/
public function testAQueuedJobNoWorkerHasReachedYetIsStillShown(): void
{
$job = new BackgroundJob($this->user, JobKind::MarkRead);
$this->em->persist($job);
$this->em->flush();
self::assertSame([$job->id], $this->visibleIds());
}
/**
* A failure stays long enough to be read, and then goes.
*
* This is the existing behaviour rather than new behaviour, and it is
* tested here because it is what makes the reaper's answer terminate: once
* a stranded job has been turned into a failure the user is told once, and
* five minutes later the indicator is empty again rather than carrying a
* new permanent fixture.
*/
public function testAFailureIsShownForItsWindowAndNotAfterwards(): void
{
$recent = $this->job(JobState::Failed, self::LONG_DEAD, finishedAt: '-10 seconds');
$this->job(JobState::Failed, self::LONG_DEAD, finishedAt: '-10 minutes');
self::assertSame([$recent->id], $this->visibleIds());
}
/**
* Everything the indicator has stopped showing, the sweep can still find.
*
* Same cutoff, complementary comparisons — `>` there, `<=` here. If the two
* ever disagreed, the rows in between would be invisible AND unreachable,
* so nothing would ever tell the user their five thousand conversations
* were not marked read.
*/
public function testWhatTheIndicatorDropsIsExactlyWhatTheSweepPicksUp(): void
{
$moving = $this->job(JobState::Running, '-30 seconds');
$stranded = $this->job(JobState::Running, self::LONG_DEAD);
$queued = $this->job(JobState::Queued, self::LONG_DEAD);
self::assertSame([$moving->id], $this->visibleIds());
$swept = array_map(
static fn (BackgroundJob $job): ?int => $job->id,
$this->repository->findStranded(new DateTimeImmutable(sprintf('-%d seconds', BackgroundJobRepository::DEFAULT_STALE_SECONDS))),
);
// Queued counts too: a job the worker never picked up at all has left
// the user waiting for something that is not coming either.
self::assertEqualsCanonicalizing([$stranded->id, $queued->id], $swept);
}
/** A job that finished cleanly is nobody's business afterwards, and never was. */
public function testASuccessDoesNotLinger(): void
{
$this->job(JobState::Done, '-30 seconds', finishedAt: '-10 seconds');
self::assertSame([], $this->visibleIds());
}
// ── Private ───────────────────────────────────────────────────────────────
/** @return list<int|null> */
private function visibleIds(): array
{
return array_map(
static fn (BackgroundJob $job): ?int => $job->id,
$this->repository->findVisibleForUser($this->user),
);
}
private function job(
JobState $state,
string $lastProgressAt,
?string $finishedAt = null,
?string $createdAt = null,
): BackgroundJob {
$job = new BackgroundJob($this->user, JobKind::MarkRead);
$job->state = $state;
$job->total = 1770;
$job->processed = 1400;
$job->lastProgressAt = new DateTimeImmutable($lastProgressAt);
$job->createdAt = new DateTimeImmutable($createdAt ?? $lastProgressAt);
$job->finishedAt = null !== $finishedAt ? new DateTimeImmutable($finishedAt) : null;
$this->em->persist($job);
$this->em->flush();
return $job;
}
private function seedUser(): User
{
$user = new User();
$user->email = 'jobs-' . uniqid('', true) . '@example.test';
$user->nameFirst = 'Jobs';
$user->nameLast = 'Fixture';
$user->roles = ['ROLE_USER'];
$user->password = 'x';
$this->em->persist($user);
$this->em->flush();
return $user;
}
}