7 September 2026

27 changes:

• Adminer answered «Invalid CSRF token» on every query, and took your session with it
• Turning the debug toolbar on from the DevPanel appeared to do nothing
• One redis connection per cache category, never closed — and the class that was never missing
• Turning the cache off did not turn the cache off
• Adminer answered «Invalid CSRF token» again, for the opposite reason — and a database password in your session file
• component_classes.breadcrumb was read before app.php was loaded
• The debug-bar switch was unstyled, unreachable on a narrow window, and its CSRF check was never registered
• calcParams() handed a second parse the first parse's results
• The queue can say when it is losing, and give back what a dead worker was holding
• Two workers could claim the same task, and a worker asked to stop kept claiming
• Every query sent a SELECT 1 first, and it broke FOUND_ROWS()
• The atomic claim was correct and slower than the race it fixed
• _(null) was a white page
• Cache invalidation walked the whole redis keyspace, once per model save
• An updated row stayed in every cached list that contained it
• Listing the cache's categories used KEYS, which blocks the server
• The queue records CPU time beside wall time, so waiting can be told from working
• The daemon orchestrator capped every pool at nine workers, silently
• The three open items from the queue inventory: burst sizing, deploy detection, and Ctrl+C
• spool:drain ran KEYS every minute, and the cache's names set never expired
• The debug-bar switch threw you to the front page, and no test could have seen why
• A redirect to HTTP_REFERER, six double decodes, and a query asked three times
• The test suite is three minutes; the default ./dockertest spends seven more on Xdebug
• form-action 'self' cancelled every SSO login that went through the login form
• The authorization endpoint redirected anywhere the request asked, with a code attached
• An OAuth server that could not say why it refused, and a logger that never truncated
• The debug switch said it was enabled and no Set-Cookie ever went out

Adminer answered «Invalid CSRF token» on every query, and took your session with it

Browsing worked. Running a query answered «Invalid CSRF token. Submit the form again.», every time. Navigation is GET and Adminer does not check it; the query form is a POST and it does — which is why the tool looked fine until somebody used it.

What it was

Adminer::display() closed this request's session and emptied $_SESSION before handing over. session_write_close() does not clear the session id. So session_id() still answered with the framework's id, and Adminer's bootstrap — which does set session_name('adminer_sid') first — found an id already there and reused it instead of reading its own cookie.

The two applications then shared one file, and each destroyed the other's contents:

Opening /adminer	wrote 15 bytes of token\|i:… over 78 bytes of session — the visitor's own session, gone
The next request	Session::start() found token as an integer, strlen() under 32, and replaced it with a fresh hex string — Adminer's token, gone

So Adminer's CSRF token never survived a round trip, and every POST failed.

How it was found

Not by reading. Three hypotheses were ruled out first, each with evidence: the origin check (<form action=""> posts to the current URL, so Sec-Fetch-Site is same-origin), the cookie path (cookie_path() resolves to a stable /adminer), and a Secure cookie the browser would refuse (Session::isHttps() only answers true for real HTTPS or a trusted X-Forwarded-Proto, so it does not lie).

What named it was counting session files on the reporting machine, by the type of the stored value rather than its contents:

token as an integer (Adminer's):   0
token as a string  (framework's):  18195
sessions holding Adminer's `pwds`:  0
total session files:               18463

Adminer's session had never once been written under an id of its own — on a machine where it had been used. Then the sequence was reproduced in that container, and it printed the answer directly: id ίδιο με του framework: true.

Fixed

handOverSession() does all three steps, and AdminerBridge::repairSession() clears the id in its own finally too — it sets one to do its repair, so without that it reintroduces exactly what the caller had just cleared.

repairSession() was written against this same collision and fixed the symptom — a poisoned token value — on the understanding that closing our session was enough to keep Adminer out of it. Closing is not enough: the id outlives the handle.

Documentation

• DevPanel guide — a note on the handover beside the Adminer section.

Turning the debug toolbar on from the DevPanel appeared to do nothing

Reported the day the screen shipped: open the DevPanel, press the button on its Debug toolbar tab, and nothing happens.

The grant was real the whole time. What was wrong was where it put you.

What it was

returnUrlFor($mountPoint) excludes the caller and Adminer from "where to go back to", so a developer page never becomes the place you return to. $mountPoint names the caller — so a second caller passing its own name replaced the panel in that list rather than joining it.

The panel's tab links to /debugbar, so the referrer on the way in is the panel. With the panel no longer excluded it became the remembered return, and enabling the grant redirected straight back to it.

And the DevPanel never carries the toolbar. renderLayout() ends in echo $html — it bypasses the framework's document, which is where the toolbar is injected. So does the /debugbar screen itself. Landing on either is indistinguishable from the grant failing.

Fixed

The exclusions are cumulative now: the caller, Adminer, and the DevPanel, plus anything a caller adds. A remembered value that is itself a developer page — written before this existed — falls back to the site root rather than being honoured.

The half that had to keep working has a test of its own: an ordinary page is still where you go back to, query string and all. Excluding developer pages is easy to overdo into "always the site root", and then somebody deep in a listing loses their place for no reason.

And it is a switch now, not a tab

Asked for directly, and it is the better shape: a tab is a place to go, and this is not one — it turns something on for your browser and should leave you where you were. As a tab it navigated away from whatever you were reading and landed you somewhere the toolbar cannot be drawn.

The strip carries a small POST form instead, with the state in the label — Debug bar: on until 15:42 — because the panel echoes its own HTML and the toolbar is never drawn there however granted it is. The label is the receipt; without it a switch that only changed a cookie is indistinguishable from one that did nothing.

It renders only for somebody above the grant floor: a control that 403s when pressed is worse than one that is absent. And it names its own tab as the return address, so pressing it keeps you on the tab you were reading — validated same-site before use, because a redirect target arriving in a POST field is an open redirect on a URL that also hands out a debug grant.

Found by looking at the installation

Not by reading. The route resolves (/debugbar answers exactly as /devpanel does, a 302 to login when signed out), the action dispatches, the guard is right — so the failure had to be after the grant, and the only thing after the grant is the redirect.

One redis connection per cache category, never closed — and the class that was never missing

Reported from production with the measurement, and it is the cause of yesterday's incident. That one was answered by containing the symptom. This is the disease.

Cache::getInstance() keeps one instance per category — rightly, so that cache:clear --category=views matches something — and every one of them built its own ConnectionManager and asked it for newConnection(), which is documented as being for a blocking SUBSCRIBE that monopolises its socket. Both halves wrong: a fresh manager has a pool of its own, so even connection() would have opened a second socket.

In a request that is invisible: the process exits. In a daemon it is one socket per category for the life of the worker.

pid=2264284  uptime=331s  fds=1024  limit=1024

1016  ESTAB 127.0.0.1:6379      ← redis
   1  ESTAB 127.0.0.1:5432      ← postgres

The class was never missing

This is the part that could not be explained yesterday, and it is worth reading twice. With no descriptors left:

1. connect() cannot open a socket, so it fails;
2. the failure takes the fallback path to memcached;
3. new MemcachedAdapter(...) needs the autoloader to open the class file — which also fails, for the same reason;
4. PHP reports what it honestly observes: Class "…\MemcachedAdapter" not found.

Which is why class_exists() returned true from a fresh process on the same machine while the error was being logged, why it never reproduced outside a daemon, and why every check of the file, the classmap, PSR-4 and opcache came back clean.

Yesterday's guess — a deploy swapping the release directory under a running daemon — was wrong. It fitted every observation, which is exactly why it was written down as a hypothesis rather than a finding. The 6 September entry has been corrected.

Fixed

ConnectionManager::forConfig() pools one manager per endpoint — host, port, database, and the password hashed into the key rather than placed in it, because array keys end up in a var_dump, a stack trace, and whatever prints one. RedisAdapter asks it for connection(), the shared one.

RedisQueueDriver had the same pattern and is the driver in the affected daemon: it neither blocks nor closes, so a dedicated socket there is one nothing will ever release.

What is deliberately not done

No __destruct that closes. The filing suggested one, and it was right about the old code and wrong about the new: the connection is shared now, so an adapter going out of scope must not take it from the adapters still using it.

Broadcasting\Drivers\RedisDriver is left alone. It also builds a fresh manager, but it has closeQuietly() — the signature of a connection meant to be owned — and publish/subscribe is the case newConnection() exists for. Reported rather than changed.

The test that found a bug in itself

testSharingTheSocketDoesNotMergeTheCategories failed on the first run: two adapters, one key each, and the second read the first's value. The code was right and the test was wrong — it handed both adapters the same key, because the prefix is not the adapter's business. Cache builds the prefixed name and passes a finished key.

Which is the reason sharing is safe here, and it is not obvious: the prefix is not set on the connection with Redis::OPT_PREFIX. If it were, a shared socket would carry whichever adapter spoke last and every category would read another's keys. That now has an assertion of its own, because it is a one-line change somebody could make in good faith.

Turning the cache off did not turn the cache off

Found while containing the connection leak above, and it is why the first mitigation appeared to do nothing: the installation set the cache to false, and the cache carried on opening redis connections.

What it was

Two switches, neither of which worked.

'method' => false fell through to defaultMethod(). The test was $this->method == '', and false == '' is true in PHP — so a line saying false selected the most capable extension installed, which is redis. The loudest available answer, not the quietest. An installation that had written it to mean "no cache here" had been running on redis for as long as the line had existed, and nobody reading the file could have known.

'caching' => false was read and then walked past. $caching is public and the constructor's settings loop copies any key matching a property onto the object — so the flag was set, and initializeAdapter() ran unconditionally a few lines later and opened the socket anyway. A switch that is read and ignored is worse than one that is absent.

Fixed

false, null, 'none', 'off', 'false' and 'disabled' all reach disableCaching(), which is the state that already existed and already had a name. caching => false gates the adapter before it is built, so a cache that is off opens nothing.

Two things deliberately unchanged, both of them the ways this could become a worse bug:

• '' and null as the constructor argument still mean "not specified" and still select the default. Every existing caller passes one of them; reading absence as refusal would turn caching off for every installation in the framework.
• '0' is not one of the words. It is what an unchecked checkbox posts. The spellings are an enumerated list rather than a falsiness test — which is the kind of test that caused this in the first place.

The third ask, declined

The filing also proposed defaulting to file instead of the most capable extension present, on the grounds that the current default is surprising. It is — but that default is itself a fix, made on 20 August after a project reported the opposite failure: in a container stack with redis running beside it, the old default asked for memcached, failed, walked down, and cached to disk while a working redis sat there. Reverting it would restore that report and answer this one, which was never the problem. The problem was that false did not mean false.

Documentation

• Cache guide — Turning it off, with the edges that were each a bug.

Adminer answered «Invalid CSRF token» again, for the opposite reason

Reported against the release that fixed the collision, from the same installation. The session collision is gone. Adminer still could not run a query — and the filing arrived with a measurement that named it: five distinct Adminer session ids in four seconds, one browser, each holding a complete, valid Adminer session that was never read again.

What it was

session_id('') does not mean work it out from the cookie. It means the id is set, to nothing, and PHP never consults the cookie again.

Measured on PHP 8.5, with session.use_strict_mode both on and off and a valid adminer_sid cookie present:

before session_start()	result
nothing	the cookie's session, resumed
session_id('')	a new session
a session started and closed, no session_id()	the closed session's id, inherited

Three states, two of them bugs, and this route has now been in both. Leaving the id alone handed Adminer our session. Clearing it — the previous fix — stopped that and started the opposite failure: a new Adminer session per request, so the CSRF token was written into a file nobody opened again and verify_token() compared a token from one session against a secret from another.

Both look like a working tool until somebody runs a query, because navigation is GET and Adminer does not check it.

And a database password in the visitor's session file

Independent of the CSRF symptom and the more urgent half. While the two sessions were one, AdminerBridge::plugin() seeded $_SESSION['pwds'] — the application's own database password, in cleartext — into the file holding logged, uid and the signed-in user's auth hash. Fixing the collision stopped it being written again; it did not remove what was already there, and a session file does not expire on its own.

handOverSession() now unsets it on the way past, on the one route the affected visitor is certain to reach.

Fixed

The handover sets the id to Adminer's own, read from its cookie. Two applications, two session files, each with its own token.

Two cookies are refused, and both matter:

• one naming this session. The original collision wrote our session id into adminer_sid, and that cookie is still in the browser of everybody who used the route before the two were separated. Honouring it walks back into the collision deliberately, on an installation that has been fixed. It is also dropped from $_COOKIE, so repairSession() — which strips a non-numeric token, correct for Adminer's session and destructive for ours — does not act on it a few lines later.
• anything that is not a session id, which is a visitor editing their own cookie. session_id() rejects those noisily, above Adminer's page.

Refused means no id at all: Adminer starts a clean session and sets its own cookie over the stale one, so the poisoning clears itself on the next request.

AdminerBridge::repairSession() puts back the id it found rather than clearing it. Clearing was right when the caller had cleared it too; now the caller has made a choice, and the repair must not override it with the one state PHP cannot recover from.

How it was found

The filing had already ruled out the cookie, cookie_path(), use_strict_mode, headers, and stripConnectionFromLinks() — each with evidence, and one of them retracting an earlier theory of its own. So the remaining question was not why Adminer lost its session but why a second and third existed at all.

Answered by running the three orderings above against a real session store rather than by reading PHP's source: the same script, the same cookie, three preambles, and the table came out of it. The previous fix and this one are the second and third rows.

Documentation

• DevPanel guide — the Adminer session note, rewritten around the three states.

component_classes.breadcrumb was read before app.php was loaded

Reported by an application whose breadcrumbs lost their styling on upgrade — and whose configuration to restore them had no effect, because the key could not be read at the moment it was asked for.

What it was

Breadcrumb::__construct() seeds listClass from ComponentClasses::get('breadcrumb'), which reads component_classes out of applicationInfo. Application::__construct() built the breadcrumb twenty-eight lines before that array existed:

line
175	$this->breadcrumbs = new \Pramnos\Html\Breadcrumb();
201	self::$appInstances['default'] = $this;
203	$this->applicationInfo = self::loadApplicationInfo(APP_PATH . DS . 'app.php');

So currentInstance() answered null, the ?-> and ?? swallowed it, and pf-breadcrumb won whatever the application had configured.

The failure was silent in both directions. Nothing said the key had been ignored, and nothing suggested that timing was the reason — a key spelled correctly and read too early is indistinguishable from one that is not read at all. The move away from hardcoding Bootstrap's class names is right, and the configuration key is the migration path offered alongside it; for breadcrumb that path was inert.

Fixed

The breadcrumb is built after app.php is read. Nothing between the two positions touches it.

And the same bug, not yet made

Pagination reads two keys in its constructor too, and is safe only because nothing builds one during boot. That is a property of the calling code, not of the class, so it is now a test: the application constructor is asserted to build exactly one Html component, and adding a second fails until somebody has checked it can see its own configuration.

Documentation

• HTML components guide — what read at construction costs, beside the sentence that says it.

The debug-bar switch was unstyled, unreachable on a narrow window, and unchecked

Reported for the second time as «it does not work», this time with a screenshot. The grant was being issued both times. Everything around it was wrong.

What the screenshot showed

An unstyled <button>. .debugbar-switch had rules in no stylesheet, so the browser's own button chrome — white, bordered, rounded — sat in a dark header looking like a tooltip somebody had left open.

And where it was

Inside <nav>: a flex item in a row of a dozen tabs that neither wrapped nor scrolled, so on a narrow window it was pushed past the right edge. Present in the markup, unreachable with a mouse. It sits beside the Back button now, and the tab strip scrolls on its own.

And why "it does not work" was a fair description of it working

renderLayout() ends in echo $html — it bypasses the framework's document, which is where the toolbar is injected. The panel cannot draw the toolbar and never will. So the entire visible outcome of a successful grant was one word changing in the switch's own caption. A control whose only receipt is that has no receipt.

The caption is an action now (Turn debug bar on, then ● Debug bar on until 15:42 — turn off), and a notice above the content says the grant is live and that the toolbar appears on the site's own pages rather than here.

The CSRF check was claimed and absent

Found by writing the test that had never been written: every existing test of this controller called postEnable() directly, so dispatch was uncovered entirely. Driving it through exec() the way a browser does turned up two things.

DebugGrantController's constructor said CsrfMiddleware validated enable and disable. Nothing did — Controller::_runThroughMiddleware() runs what a controller registers, and this one registered none, so the token field the form has always carried was read by nobody. A claimed check is worse than an absent one, because it is the reason nobody looks.

It is registered now, under postenable and postdisable: exec() resolves POST enable to postenable and passes that name to the pipeline, so a middleware filed under enable would have looked exactly like this fix and changed nothing. Both spellings are asserted.

And GET /debugbar/enable was a fatal

The same test found it. exec() looks for postEnable only when the request is not a GET; on a GET it falls through to $this->enable(), which did not exist — Call to undefined method, a 500 on a live server from a bookmark of the form's own address, or a crawler following one. It answers 405 with the screen now: the address is right, the method is wrong.

And the screen was two documents in one response

Reported with a second screenshot, from /debugbar/enable on a live installation: the admin theme's sidebar and breadcrumb, wrapped around the debug screen's own <html>.

screen() and refuse() return complete <!doctype html> documents, and every caller echoed one and then returned — so the framework carried on and rendered the application's document around it. The buttons were in there somewhere; the page read as broken rather than as an answer.

They end the response now, the way DevPanelController::renderLayout() does, with the same terminate() seam so a test can drive them without exit taking the runner with it.

The same screenshot answered the other half of «it does not work» on that installation: the page it was showing is the no-application-key branch — No application key: nothing to sign a debug token with. Run \php pramnos key:generate` first.` The grant route was working and saying so, one line above the crop, inside a page that had the application's chrome wrapped around it.

Documentation

• Debugging guide — the switch's placement and why the panel cannot show the toolbar, the CSRF/405 behaviour of the two actions, and what «No application key» means there.

calcParams() handed a second parse the first parse's results

Reported by a consuming application as FW-061, one that re-parses the request on every page: every URL carries a language prefix, so the first segment is cut and calcParams() called again. Nine such calls per request — one for the language, the rest for slug rewrites.

What it was

Keeping $_GET instead of emptying it was right about foreign keys — a rewrite, a middleware or a test may have written one, and discarding it silently was the bug that change fixed — and wrong about the keys the method produces itself:

el/parent/skipjobpost                   1st: _option='skipjobpost'   2nd: 'skipjobpost'
el/parent/skipjobpost/anazitisi^athina  1st: _option=null            2nd: 'anazitisi^athina'

On the second parse parent/skipjobpost is controller plus action and produces no _option at all, so the correct answer is absent. Instead it kept the action's own name, from the parse where the prefix had shifted every index by one — and an action whose _option names itself routes to itself. Which is the bug the filing was chasing.

The path pairs had the worse version of it. The pairing loop writes a key only when !isset($_GET[$varname]), so a surviving pair does not merely linger — it blocks the new value. page/view/k/first followed by page/view/k/second answered first.

Fixed

The keys are recorded as they are written, and taken back on the next call. Recorded rather than matched by a pattern, because "the keys this method produces" is not a fixed list: _option, and one key per pair of trailing path segments, named by the URL. A pattern would either miss them or take somebody else's.

Cleared before the query string is merged, so ?_option=x still wins. Forgotten by resetInstance(), like $action and $_controller beside it — a static that survives a reset is how one test comes to depend on the one before it.

The two tests that could not fail

Written first against filter => new, which is not what that URL pairs. el/jobs/list/filter/new pairs list => filter — the prefix shifts every index — so both assertions were true whatever the code did, and reverting the fix left them green. Both now assert the first parse's output before testing that the second clears it.

Documentation

• Routing guide — Calling it twice on one request, beside the decomposition table.

The queue can say when it is losing, and give back what a dead worker was holding

Two filings from the same night, in which a production queue fell four hours behind because one worker was serving a type receiving 6.1 items a second — a single worker tops out at 4.4 — and nobody noticed until the backlog was 175,000.

Both were filed as design questions, and both ranked their own asks. Taking them in that order rather than in the order of ambition: reclamation, then the losing-queue signal, then the pool. The first two are small and pay immediately; the third is the one that gets asked for first, and it would have hidden that night rather than surfaced it.

Tasks whose worker died — queue:reclaim

A worker claims a task with status = 'processing' and a lock expiry. If it then dies — a fatal, an OOM kill, a machine going away — nothing writes the end of that story, because a process that dies cannot record its own failure.

getNextTask() does pick up a stalled row, and the filing was generous about not mentioning it. It does not cover the two cases that hurt: a type whose workers are all dead reclaims nothing, because the reclaim is a side effect of somebody asking for work; and a row that has used all its attempts fails the stalled branch's own condition, so it stays processing for ever — never claimed, never failed, counted as in progress by getStats(), invisible to queue:cleanup, which reads only terminal states.

That second one is measurable, and the filing measured it: a fatal killing workers leaked 101 tasks and only 34 were recorded as failed. The ledger under-reported the damage threefold, so the incident read as a slow queue rather than a queue losing work.

QueueManager::reclaimAbandonedTasks() requeues the rows with attempts left and records the rest as failed, with a reason. The lock expiry is the entire safety condition, which is what makes it safe against a live queue: a worker that is alive holds a lock that has not expired, so nothing running can lose what it holds. attempts is never spent by a reclaim, so a task whose worker keeps dying still walks up to maxattempts and stops.

queue:cleanup runs it before purging, so an installation that already schedules a cleanup gets this without editing its crontab — which is where a fix like this is otherwise lost. --no-reclaim opts out.

Whether the queue is keeping up — queue:health

A depth is a level; this is a rate. The dashboard read "a few thousand pending" for most of those four hours, and it was not wrong — the level was moving slowly. The number that would have caught it in the first hour was arrivals against completions, and it was on no screen.

QueueManager::throughput() answers it and queue:health prints it. The exit status is the point: 1 when the queue is losing, so cron mails it and a monitor pages on it with nothing parsing the output.

--per-type is the flag to use, and the reason is the reported incident exactly: the totals across every queue were healthy and one type inside them was not. An alert watching only the sum fires when the backlog is large enough to move the sum, which is hours late. The types broken down come from the table rather than from the directory of handler classes — a type with a handler and no traffic is noise, and a type with traffic and no handler is the thing somebody needs to see, because the worker fails every one of those.

Completions count every terminal state, failures included: a task that failed is one the queue is no longer carrying, and counting only successes reports a losing queue during an outage where the work really is draining away. A retryable failure is not a departure — markTaskAsFailed() returns it to pending while attempts remain. Both halves have a test, and the second one caught the first version of that test being wrong.

The index

count(*) WHERE status = ? AND type = ? was a sequential scan: 98 ms and 50,365 buffers on 175,000 rows, five times a minute, for a number that changes slowly. The existing (status, priority, createdat) leads with status and does not carry type.

idx_queueitems_status_type — added, not replacing anything, because (status, priority, createdat) is what getNextTask() orders by and trading a fast claim for a fast count is not a trade.

What is deliberately not shipped

The pool. Both filings say the orchestrator stays theirs for now, and that is right: queue:process --daemon is a complete worker — signals, lock file, graceful stop on SIGTERM and SIGINT with the task in hand finished first — and how many run, noticing when one dies and restarting it is a supervisor's job.

The autoscaler. The second filing describes a working one and then argues against it better than anything here could: "Elasticity hides the thing it absorbs… An autoscaler would have absorbed that silently and the misconfiguration would still be there, paid for in CPU." Its three constraints are recorded in the guide for whoever builds one — one step per cycle, load gates growth but never shrinking, two thresholds with a gap — because they were learned the expensive way and the fields are the easy part.

Documentation

• Queue guide — Keeping the durable queue honest. The guide had documented only the delayed queue; the durable one's operational side had no page at all.

Two workers could claim the same task, and a worker asked to stop kept claiming

Neither of these was filed. Both were found while answering the queue filings above, and both are the same defect from different ends: work claimed that should not have been.

The claim was not atomic, and the docblock said it was

getNextTask() read a row and then called $task->save(), which writes every column of the loaded model. Two workers polling the same queue could read the same row and both save over it:

• both ran the task;
• the second one's lockedby won, so the row named a worker that was not the only one running it;
• attempts carried a single increment for two executions.

Nothing in the data said it had happened. The window is the gap between the read and the write — small, entered by every worker on every poll, and hit more often the more workers a queue has. The comment above it read "atomically claim the task", which is the kind of comment that stops anybody looking.

Fixed with a guarded UPDATE: the state the row was read in becomes the WHERE clause and the database decides. Zero rows affected means somebody else was first, which is not an error — the next candidate's turn. Workers now look at a few candidates per pass rather than one, because with one a worker that loses a race reports "queue empty" and sleeps with work waiting.

For a stalled row the lock we read is part of the condition, compared by value rather than re-tested against NOW(): status is processing either way, and the question is is this still the claim I read? Without it a worker could take a row from a live worker that had claimed it in the meantime.

attempts is incremented by the database (attempts + 1) rather than read and written in PHP — the same race one level down, and markTaskAsFailed() compares it against maxattempts to choose between a retry and a permanent failure.

Chosen over SELECT … FOR UPDATE SKIP LOCKED, which both backends support, because that needs a transaction held across the claim and this method is called from inside whatever transaction the caller already has. A conditional update needs nothing and cannot deadlock.

And a graceful stop was only graceful between batches

The daemon loop checks shouldStop() on each pass, and the comment above it said "the current batch finishes before the process exits". With the default --batch=20 that is up to twenty more tasks claimed after the signal — because processBatch() never consulted the flag at all.

Which matters because of what happens next: systemd's TimeoutStopSec is 90 seconds by default, so a batch that outlasts it is SIGKILLed mid-task and the row it was holding is left processing behind a lock nobody holds. That is the leak queue:reclaim exists to clean up, produced by the code whose job is to stop cleanly.

The flag is checked between tasks now, before each claim rather than after each task, so the task in hand always finishes and nothing new is taken. Which is what the comment already claimed.

And a lock file removed under a worker was ignored inside the batch

Found by reading the application's own implementation, which had a condition the framework's did not: a missing lock file is a stop request. It is how an orchestrator reclaims a slot — delete the lock, expect the holder to leave — and ProcessQueue's daemon loop checked for it while shouldStop() did not. So with the per-task check added above, a worker inside a batch still kept claiming after its lock had been taken away.

shouldStop() now answers all three ways a stop is asked for: a signal, the .stop sentinel, and the vanished lock.

Guarded on the lock having been held, which their code also does and which is not a detail: a one-shot CLI run or a test never writes a job file, and read literally that absence says stop from the first check onwards. Their comment records their suite catching exactly that — a batch that should have processed two tasks processed one — so the guard is here before the same lesson had to be learned twice.

The graceful-stop work the filing reported building

One filing said a graceful stop was implemented on the application's side: SIGTERM handled where only SIGINT was, and a handler no longer releasing the lock file while a task is held. The framework already had both — SignalStop traps SIGTERM and SIGINT and only raises a flag, and WorkerLock::release() is called at a safe point and never from a handler.

But their version was not redundant, and the first draft of this entry said it was. Reading it turned up two things the framework did not have: the vanished-lock check above, now upstream, and SIG_IGN for SIGINT on a supervised worker — Ctrl+C is not how an orchestrator asks a worker to leave, and a stray interrupt to the process group should not stop it. The second is still theirs. Filed back to them as a mapping rather than as "delete yours".

Every query sent a SELECT 1 first, and it broke FOUND_ROWS()

Reported by a consuming application as FW-062, with the MariaDB general log from one page load:

total_queries=476   select1_pings=355

75% of the statements were the framework's own. getConnection() asked isConnectionAlive() on every call, and on MySQL that probes with SELECT 1 — so every query became two, and more than two per query, because getConnection() is called from outside runQuery() as well.

The round trip was the smaller half

FOUND_ROWS() is per-connection state: it reports the row count of the last statement on that connection. With a probe in between, the last statement is always SELECT 1 — one row. From the reporting log, in order, on one connection:

Query  select SQL_CALC_FOUND_ROWS *, c.* from `pramnos_prostoclassifieds` c …
Query  SELECT 1
Query  SELECT FOUND_ROWS() cnt

The same pair answers 0 in the mysql client and 1 through the framework. It surfaced as a classified ad with no professionals in it reporting "All (1) / Interview (1) / Favourites (1)" above an empty list — a count that was not a count of anything, in a place no reader would suspect the database layer.

Reproduced here, and the numbers are the same shape: with the probe restored, a limited select over seven rows reports FOUND_ROWS() = 1, an UPDATE touching three rows reports ROW_COUNT() = -1, and five queries send eleven statements.

Fixed by remembering instead of asking

isConnectionGone() already decides whether a connection is dead, at the one moment the answer is knowable — when a statement has just failed. That answer was being thrown away, so every later caller had to rediscover it with a round trip of its own. It is recorded now, and getConnection() replaces a link that has been marked.

PostgreSQL keeps its check: pg_connection_status() is a local read of a cached state rather than a statement, so it costs nothing — and it is the one engine where a free check exists. mysqli::ping() was the obvious substitute and is deprecated in PHP 8.4, so there is no cheap protocol-level equivalent to reach for.

The recovery path is not weakened by this: a statement on a connection that died while the process was idle fails, isConnectionGone() says why, the connection is replaced and the statement is retried. That path has its own integration tests, which kill the connection from a second session with the server's own KILL, and they still pass.

isConnectionAlive() is unchanged and still public — probing deliberately is a reasonable thing to do, and an application may be calling it. Its docblock now says what it costs.

What breaks in subclasses

Nothing, if you have not overridden isConnectionGone(). No signature changed and no method was removed.

If you have overridden it, nothing to do either — and that took a second attempt to get right. The obvious place to record "this connection is gone" was inside isConnectionGone() itself, and it is protected: recorded there, an override would answer gone with nothing writing it down, so getConnection() would hand the dead link straight back and the retry would fail. A reconnect broken for exactly the installations that cared enough to customise it, and invisible in the diff.

The call sites record it instead, so an override remains the only thing deciding. There is a test that drives the whole path through a subclass which answers the question itself and never calls the parent.

What the filing did on its own side

SQL_CALC_FOUND_ROWS/FOUND_ROWS() was replaced with a separate count(*), which does not depend on connection state and is what MySQL 8 recommends anyway — and the filing says explicitly that this is not to be reverted when the framework is fixed. It also scanned src, app, www, bin and its own vendor/mrpc for FOUND_ROWS, LAST_INSERT_ID, ROW_COUNT and @user_variables and found no other site, and left a test holding that at zero. Which is the difference between a workaround and a fix, and it is worth naming.

Documentation

• Database API guide — the reconnect section, which said getConnection() probes the handle and described that as covering the idle case.

The atomic claim was correct and slower than the race it fixed

Not a filing. The application that had asked for the queue work took this morning's atomic claim, ran it against twelve workers, and measured it — then fixed it on their side and wrote down what they found. Both halves are now upstream, and one of them is a defect in what shipped this morning.

What they measured

3 workers,  non-atomic save()                  11 tasks/second
12 workers, atomic claim + retry loop           9.2 tasks/second

Worse, with four times the workers. And invisible in the metric everybody was quoting, because execution_time times the handler and nothing else — the cost was in the selections being thrown away.

A lost race was spelled the same way as an empty queue

This is the defect, and it is mine. Selection is deterministic — ORDER BY priority ASC, createdat ASC hands every worker the same oldest row — so making the claim atomic turned everybody wins into ten losers per eleven asks. A loser got false, processNextTask() passed it up, and processBatch() reads false as nothing left: it broke out of the batch and the worker slept five seconds. Ten of eleven workers spent their lives losing races and sleeping, with work waiting.

Looking at five candidates per pass instead of one made it less likely and not less true: the same five go to everybody.

A pass that was offered rows and won none is retried now, up to ten passes. The winner has already marked its row processing, so the next pass is offered the one below and the pool converges on distinct rows. A pass offered nothing still answers false at once — an idle poll is what a worker does most of the time and it must not cost ten selections.

And the retry loop should mostly not be needed

FOR UPDATE SKIP LOCKED removes the collision instead of recovering from it. The subquery locks the row it picks; a worker arriving while that lock is held is neither queued behind it nor a loser — it is offered the next unlocked row.

I had declined this in the morning's commit, on the grounds that it needs a transaction held across the claim while getNextTask() runs inside whatever transaction the caller has. That reasoning was about a two-statement form. Their version is one statement — UPDATE … WHERE taskid = (SELECT … FOR UPDATE SKIP LOCKED LIMIT 1) RETURNING taskid — whose own implicit transaction holds the lock, and there is nothing to hold across anything.

Verified here per engine rather than assumed, because the two do not agree:

PostgreSQL 14	the single statement works, RETURNING and all
MySQL 8.0.46	error 1093 — you can't specify target table for update in FROM clause — and no UPDATE … RETURNING

So MySQL and MariaDB get a locking SELECT and a guarded UPDATE inside a transaction of the queue's own, and that path steps aside when the caller already has a transaction open — committing inside somebody else's would commit their work. A server without SKIP LOCKED refuses once, the refusal is remembered for the process, and everything falls back to the loop.

A derived table is the trap to avoid. … WHERE taskid = (SELECT t FROM (SELECT taskid AS t … FOR UPDATE SKIP LOCKED) x) gets past 1093 on MySQL — it returned OK when tested — and is wrong: the subquery is materialised, so the lock is taken on a copy and SKIP LOCKED means nothing. It would look like the fix and collide exactly as before.

On their two indexes, and mine

They added a partial index for the claim path after measuring a parallel sequential scan at 73 ms and 52,309 buffers — and then reverted it the same day, because pg_stat_user_indexes said the framework's existing (status, priority, createdat) had served that query 113,437,830 times against 6,309 for theirs in the twenty minutes it existed. Their own note: "I had grepped the wrong branch" — the measurement was of createdat DESC, which only --reverse produces and no worker passes.

So no new index here, and one confirmation: their revert says idx_queueitems_status_type — this morning's — stays, because it serves the per-type backlog count that the ordering indexes cannot.

The test that could not fail, again

The first version of the lost-race test overrode attemptClaim() and returned null from the test itself — so it supplied the very answer it was checking, and the production line could be replaced with return false while it stayed green. It drives the real method now, with claimRow() refusing everything, which is what a worker that loses every race actually sees.

Documentation

• Queue guide — One claim, one worker, rewritten around the single statement, with the engine differences and the derived-table trap.

_(null) was a white page

Reported by a consuming application as FW-063.

Language::_() is declared _($string = '', $args = '') — no type, and a default, which says anything is accepted and nothing is fine. It then used the value as an array offset and handed it to onMissingString(string $string), which is typed:

Deprecated:  Using null as an array offset
Fatal error: onMissingString(): Argument #1 ($string) must be of type string, null given

A declaration and a behaviour saying different things, where the cost of the difference is the whole response rather than one wrong word.

Not theoretical. Fifteen templates in the reporting application build lists this way:

$x = @unserialize($this->model->something);
if (!is_array($x)) { $x = array(); $x[] = $this->model->something; }
foreach ($x as $item) { $lang->_($item); }

The property is null whenever the user left the field empty — the values live in a separate key/value table, so blank means no row. One search page answered 500 to a signed-in visitor because of it. On the legacy class the same call came back empty and the page rendered.

Fixed

An empty key gets an empty answer. null, false and '' are the same absence spelled three ways, and they are silent, because that is how a template spells it. A number is a usable key and becomes its own string. Everything else — an array, true, a non-stringable object — cannot be a key: still '', so the page renders, and logged, because that call site has a real bug.

onMissingString() keeps its type and is now only ever handed a string, which is asserted at the seam rather than through the symptom: the hook is overridable, and an application's override must not have to defend itself against a null the framework let through.

And addlang() was losing numeric keys

Found by the test for the line above, and it could not have been found any other way. PHP stores '7' => '…' in an array literal as the integer 7, and array_merge() renumbers integer keys rather than preserving them — so a catalogue entry keyed by number arrived under whatever index came next. Not a missing translation: a translation filed under a key nobody would ever look up.

Invisible until _() started asking for '7' correctly, at which point a test that should have passed did not. ((array) $strings) + $this->_strings instead — identical for string keys, since + keeps the left side and the new strings are on the left, and correct for numeric ones.

A comment that was wrong, and the mutation that said so

The first version special-cased true alongside null and false, with a comment claiming (string) true is '1' — "a key that looks deliberate and never matches anything". Reverting that special case changed no behaviour at all, because is_int(true) is false and true was already falling through to the same empty answer. The mutation check caught it: a branch whose removal changes nothing was not carrying the reason its comment gave.

true falls through to the logged branch now, which is the honest place for it — the same empty string, and unlike false it is nobody's way of spelling no value.

Documentation

• Internationalization guide — A key that is not a string, with the template shape that reported it.

Cache invalidation walked the whole redis keyspace, once per model save

Filed as urgent, and it earns it: this is why one installation's cache was switched off, and why four other explanations for a slow queue looked right first.

Model::save() calls cacheflush($key) — a per-entity key where cacheflush() expects a category. RedisAdapter::clear($category) fell back to SCAN … MATCH whenever it had no marker for a category name, and there was never a marker for a key-shaped name, so the fallback ran on every save. And SCAN … MATCH filters what it returns, not what it traverses: every call walks the whole database.

Then each fallback wrote a permanent marker for a category with no members. So the structure that existed to make category invalidation cheap was the structure that made it unaffordable, and it grew without bound.

keys in the database          288,706
keys with a TTL                13,792     ← 95% were markers left by sweeps that found nothing
round trips per sweep          ~1,443     (COUNT 200)
worker CPU                       1.6%     — in do_poll in 148 of 150 samples
wall clock per task             0.932 s
redis clients in SCAN               20    concurrently

Because the cost is per save and per worker, adding workers made throughput worse: three moved 11 tasks a second, eighteen moved 8.6.

Fixed

clearCategory() reads the index set and nothing else — O(members). The pattern sweep and the marker are both gone: the sweep existed for a crossover, and an installation upgrading past this runs cache:clear once, which is one deliberate sweep by an operator and is on most deploy scripts already. Entries an older build wrote otherwise leave on their own TTL.

The index sets are bounded and always were — each save pushes the set's expiry to an hour past its newest member, so it outlives its members and dies when writing stops. The markers were the unbounded half, which answers the filing's second question: it is not the index that needed a TTL.

getCategories() read those markers to enumerate categories, so it now reads the index sets — which also means the listing stops reporting categories that no longer hold anything.

And getAllItems($category) reads the same index. It had matched <prefix><category>_* while Cache writes <prefix>_<category>_<id>… — the underscore after the prefix was missing, so every category read as empty on the cache dashboard while the flush was emptying it. Two answers to one question that disagreed; one source of truth now. That was a second filing's bug, closed by the same change.

The third question: two flushes per save

They are the two branches of one if — the specific key when there is a primary key, the category otherwise — so it was one flush per update, and two on a delete where both are wanted. What was true is that either of them walked the keyspace.

The specific-key flush is kept rather than dropped as dead work: _load() passes false for caching, so nothing in the framework writes under that name, but a subclass that turns per-entity caching on needs exactly this invalidation — and it now costs one SMEMBERS on a key that is not there.

And the smaller ask, which was the most valuable line in the filing

"A cache whose invalidation is O(keyspace) should say so somewhere. A slow-operation log line above some threshold, or a counter, would have turned four hours into ten minutes."

A keyspace sweep now logs its round trips, the keys it removed and the time it took, under cache, above 250 ms — with the sentence that matters in it: SCAN filters what it returns, not what it traverses, so this costs the size of the whole database. If it is happening on a write path rather than from cache:clear, that is the thing to fix.

Above a threshold rather than always, because a line nobody reads is the same as no line and a deploy-time clear on a large cache is meant to be slow.

Why it took four hours

Worth recording, because the framework's own instrumentation is what failed. The queue's execution_time measures wall clock around the handler, so a handler using 1.6% of a core and waiting on redis is indistinguishable from a slow handler — and every wrong hypothesis explained a large number: the atomic claim (innocent, rewritten twice), a missing index on the claim path (added, then reverted), TimescaleDB compression on a table the handler reads (real, and not this), the handler being CPU-bound (it was not).

cat /proc/<pid>/wchan said do_poll and redis-cli client list said twenty clients were scanning. Nothing in the framework pointed there, which is what the log line above is for.

What breaks in subclasses

Nothing by signature. Two behaviours changed, and both were the bug:

• A category clear only removes what was indexed. An adapter told nothing about a key's category cannot know it — the index is written at save time, by Cache, which does tell it. A test that saved keys directly and expected the category to be inferred from their names passed only because of the sweep; it sets the category now, as the real caller does.
• categoryMarkerKey() is still there and nothing writes it. Left in place because it is protected and an application may call it. purgeCategoryMarkers() is new, for removing what an older build left without discarding a warm cache.

Documentation

• Cache guide — What invalidation costs, and the shape that made it ruinous, including how to recognise it from outside PHP.

An updated row stayed in every cached list that contained it

Found by answering a question about the entry above — is the invalidation smart enough? It was too smart by one step, and the step it skipped was the one that mattered.

Model::save() on an update cleared only <id>-<table>. The comment above it said "clear only the specific record's cache, not the entire category", which is the right instinct and the wrong conclusion: a list is not the record, and it contains it. And nothing writes to that per-entity category — _load() passes false for caching — so the ordinary path of loading a row, changing a field and saving it invalidated nothing at all.

A list cached under $useCacheInLists kept serving the value the row used to have.

	before	now
insert	the category	the category
update with a primary key	<id>-<table> only — a category nothing writes to	the category, and <id>-<table>
update with no primary key	the category	the category
delete	both	both
save() with no changes	nothing	nothing

Reproduced before it was believed: read a list, load the row, change a field, save, read the list again. Both backends — the SERIAL key comes back from a RETURNING clause on PostgreSQL and from getInsertId() on MySQL, and it is the presence of the key that chose which flush ran, so "invalidated nothing" could have been true on one and not the other.

Invisible because it is cheap to not notice. The default TTL is 60 seconds, so the page is right again by the second reload — an intermittent staleness that reads as somebody else's problem. Exactly the shape of the settings cache reported the same day: a write that saved and a screen that redrew from before it.

And it is only affordable to fix today. A category flush was a SCAN … MATCH over the whole redis keyspace; adding this call yesterday would have doubled the very cost that made the cache unusable. It is a SMEMBERS and a DEL of that category's own keys now.

The other half of the question: is there a switch?

Yes, and it was already right. protected $useCacheInLists — off by default — with $cacheInListsTime. Both per model, so a write-heavy table opts out on its own rather than the installation turning caching off. And save() already returns early when getChanges() is empty, so a no-op save costs a comparison rather than a write and a flush — which is why making the update path invalidate more does not turn a liberal save() loop into a flush storm.

What is not worth adding, for the record: coalescing several flushes of one category into one per request. It is real — a handler saving fifty rows flushes fifty times — but it needs machinery, and a request that dies between the last save and the deferred flush leaves a stale cache. A wrong cache is worse than a slow one.

Documentation

• Cache guide — Turning a model's cache off — and when to, and When a change invalidates what.

Listing the cache's categories used KEYS, which blocks the server

Asked directly: why do we scan instead of keeping a central index key? For invalidation we do keep one — that is the fix earlier today. For enumeration there was none, and the question was right.

getCategories() asked redis which keys match catindex:*, and getStats() counted keys(<prefix>*). Both are KEYS: O(the whole database), and single-threaded — redis serves nothing else while it runs. So opening a cache dashboard stalled every application sharing the instance, in proportion to how much was in it. The same mistake as the invalidation sweep, one screen further out, and worse in kind: SCAN at least lets other clients in between its steps.

What redis holds now

key	what it is	bounded by
<prefix>_<category>_<id>.…	a cache entry	its own TTL
<prefix>catindex:<category>	a set of that category's keys	its members' TTLs
<prefix>catnames	new — a set of the category names	the schema, one member per category

Invalidating a category is SMEMBERS + DEL; listing them is one SMEMBERS; the item count is a sCard per category. Nothing asks redis to find anything.

And it is pruned, because the last central key was not

The structure this replaces was catindexed:<category> — one marker per category-clear, no TTL — and Model::save() supplied a fresh category name per entity, so it grew by one key per row saved, for ever. 275,000 of them on one installation, 95% of its keyspace, each one making the sweeps they existed to avoid slower. A central index that only grows is the same bug with a nicer name.

catnames holds names, not entities: bounded by the schema rather than by the data. And it shrinks from both ends — a cleared category is removed by the clear, and a category whose last entry simply expired is removed the next time the list is read. Both halves have a test, and the first version of that test only had one: reading the list before checking the set let the lazy prune hide a missing sRem() in the clear, so removing it stayed green.

What still walks the keyspace, deliberately

cache:clear with no category, because it means everything — including entries written with no category, which are in no index. And the "all items" listing, for the same reason; that one moved from KEYS to SCAN, so a diagnostic screen can no longer stall the instance.

getStats()' item count is summed from the category sets, so an entry with no category is not counted. A number that is slightly low, over a tile that can stall production.

Documentation

• Cache guide — What redis keeps, and why nothing scans, with the three keys and what bounds each.

The queue records CPU time beside wall time, so waiting can be told from working

An application filed an inventory of seven pieces of queue work it had built and offered upstream. Six were already answered today — reclamation, graceful stop, the one-statement claim, the backlog index, per-type throughput, and the pool deliberately left where it is. The seventh was under a different heading: "one thing we would ask for that we could not build."

"execution_time in the queue is wall clock around the handler, and last night four wrong diagnoses all fitted it… A queue that recorded CPU time beside wall time per task would have said 'these tasks are not computing' in the first ten minutes."

They are right, and it is squarely framework work: nobody but the worker is in a position to measure it.

What it is

Worker::processNextTask() takes getrusage() on either side of the handler and stores user plus system CPU in a new queueitems.cpu_time. throughput() reports wall, cpu and computing — the ratio — and queue:health says the conclusion in words:

These tasks are not computing: 1.6% of their wall clock was CPU. They are waiting on
something — a database, redis, an HTTP call. More workers will not help; whatever they
wait for is already the limit.

Which is the sentence that would have replaced four hours with ten minutes, and it points the opposite way from a high ratio: computing means faster code or more cores, waiting means adding workers makes it worse.

null, not 0.0, where nothing measured it — an older row, a platform without getrusage(). Nobody measured and did no work are opposite conclusions, and the second sends somebody hunting a phantom bottleneck.

Written onto the task rather than passed to markTaskAsCompleted(), which is public and overridable: a fifth argument there is a fatal at class load for every application with its own.

And an honest completion time

Their §7 correction, taken with it. clears_in answers null when the queue will not clear — because dividing the backlog by the completion rate produces a figure that recedes on every refresh, so a queue reads as nearly finished right until it obviously is not. The rate is the net rate, since work arriving during the drain has to be drained too.

On the rest of the inventory

• §1, §3, §6, §7 — already upstream today, and their own numbers are in the docblocks. Their revert of the claim-path index confirms idx_queueitems_status_type earns its place.
• §2 — the framework already traps SIGTERM and SIGINT in a flag-only handler and never releases the lock from it; the batch-boundary gap and the vanished-lock check are today's. Their SIG_IGN for SIGINT on a supervised worker is still theirs and still worth having: it needs a definition of supervised the framework can state.
• §5, and this is the one to tell them — the packed-refs trap does not apply here. \Pramnos\Framework\GitInfo already falls back to packed-refs and already skips the # header and the ^ peel lines. Their own hand-rolled reader is what had the hole; using GitInfo closes it, including for the version banners and cache-busting keys their filing correctly points out have the same shape.

Documentation

• Queue guide — Waiting is not working, and clears_in — and why it is often null.

The daemon orchestrator capped every pool at nine workers, silently

From a re-read of the queue inventory, under a heading added after the first pass: "the trap that made all of §4 look broken". It is in DaemonOrchestrator, which the framework ships — so this is not their bug reported to us, it is ours found by them.

findRunningPidsByWorkerSignature() recognised its own processes with

$needle = '--worker-id ' . $workerId;
strpos(str_replace("\0", ' ', $cmdline), $needle) !== false

A substring test matches a prefix. worker-1 is found inside worker-10, worker-11, worker-12 — so deduplicateRunningProcesses(), whose whole job is killing genuine double-spawns, killed workers 10 and above as duplicates of worker 1 within a cycle of being spawned. Every pool was capped at nine per profile, whatever the ceiling said, and the journal said so every 31 seconds for hours:

[started] queue-getnetworkserverdata-10 pid=293679
[started] queue-getnetworkserverdata-11 pid=294639
[dedup]   killed duplicate queue-getnetworkserverdata-1 pid=293679
[dedup]   killed duplicate queue-getnetworkserverdata-1 pid=294639
[exited]  queue-getnetworkserverdata-10 — daemon shutdown cleanly

Where the symptom pointed

Not here. "Burst is not working" was investigated three times against the thresholds, the load gate and the stored settings — and each investigation correctly confirmed the policy and therefore concluded the configuration must be wrong. The backlog was twenty thousand above the trigger, the load gate was open at 0.63 against a ceiling of 0.75, and the target function returned current + 1 when computed by hand with the live numbers. The policy was asking for eleven workers and getting them; something else was killing two of them every cycle.

Their conclusion is in the guide now, because it generalises past this bug: a scaling controller needs its decision and the resulting process count logged side by side, or a supervisor that undoes its own decisions is indistinguishable from one that never makes them.

Fixed

cmdline is NUL-separated, so the arguments arrive already delimited — they are compared as values now, which removes the question rather than answering it. Both --worker-id x and --worker-id=x are understood, an absent option matches nothing rather than everything, and an empty id matches nothing rather than every process on the machine.

The ps aux fallback, for a platform with no /proc, gets one space-joined string and has no values to compare — there the match is bounded by whitespace or end of line, and the id is quoted so a . in one is a literal rather than a wildcard. Easy to fix one path and leave the other, and the other is the one nobody runs until somebody does.

Nine is not a special number. It is the boundary only because ids are decimal, and the test asserts both directions plus worker-1 against worker-100 — a fix that compared lengths, or that only guarded the short-against-long case, would pass half of it.

Documentation

• Workers & daemons guide — Worker ids are compared, not searched for.

The three open items from the queue inventory

Everything left over from the seven-piece inventory, closed.

§4 — Console\BurstPolicy

How many workers one queue should have, as arithmetic and nothing else: floor, ceiling, running count, backlog, thresholds and load in, a number out. No queue, no database, no process table, no clock — which is the contributing installation's own advice, and the reason is that a scaling decision only exercisable by arranging a real overloaded system is one nobody dares change.

Their four rules are in it, and the fifth found itself. Their earlier filing said "plus a cooldown — otherwise the reconcile interval becomes the frequency of the oscillation", and the first version here had the four fields and not that. The settling simulation went red with 2,3,4,5,6,7,8,8,7,6,5,4,3,2,2,2,2,3,4,4 — the ceiling, then the floor, from a load three workers can serve and thresholds that look perfectly reasonable. Which is the whole argument for simulating a scaling decision instead of reasoning about it.

And a second wrong expectation of mine, corrected by the same test. I asserted the pool settles. It cannot: a pool is a whole number of workers and the load it serves usually is not, so at three-point-something workers the pool must walk 3,4,3,2,3,4… for ever. The guarantee is a bound, not a fixed point — within one worker either side of what the load needs, a span of two. That bound is exactly what the cooldown buys; without it the span is six. Both are asserted, the second as an oscillation so removing the cooldown reddens something.

The load gate's asymmetry has a test that actually distinguishes it, which took two goes: with a backlog above the grow threshold the decision is made in the grow branch and "held" is the answer whether or not load also sheds, so the first assertion passed a policy that shed on load. A backlog inside the gap with the machine on fire is the case that tells them apart.

§5 — deploy detection, and the trap the framework had too

DaemonOrchestrator already detected a new commit and re-exec'd itself. But getCurrentGitHash() read .git/HEAD, followed the ref: to .git/refs/heads/<branch>, and returned '' when that file was not there — which is right until git gc packs the refs and deletes the loose files. git gc --auto does that unattended, on a schedule nobody chose.

The failure shape is why it matters. Nothing errors: an unreadable hash is correctly treated as cannot tell, the loop keeps its last known value, and deploys simply stop restarting anything. No exception, no log line, no failed deploy — new code sitting on disk while the old process runs.

Framework\GitInfo already handled both layouts, including the # header and the ^<sha> peel lines. So the fix is to ask it, and the reader is now behind a seam a test can point at a repository it builds — because ROOT is a constant and a constant is not something a test can vary.

Worth repeating their own note: any code inferring a deployed version from the filesystem has this hole. A version banner, a cache-busting key, a health endpoint reporting a build. GitInfo is the answer for all of them.

§2's remainder — SIGINT on a supervised worker

SIGTERM is how a supervisor asks a worker to leave, and it was already trapped. Ctrl+C is not: a supervised worker has no terminal, so a SIGINT reaching it came from somewhere it was not addressed — an operator interrupting a shell that shares the process group, a script signalling a group rather than a pid. A pool that goes down for a keystroke in a neighbouring window is a pool that goes down for a keystroke.

SIG_IGN rather than a trap that does nothing, because the default action for SIGINT is termination: an untrapped one kills the process outright, mid-task, and the row it held is left processing behind a lock nobody holds — the leak queue:reclaim exists to clean up.

Only when supervised, and supervised needed a definition the framework could state rather than guess. It had one: PRAMNOS_JOB_LOCK_FILE, which is how a supervisor hands the lock path down, and isSupervised() was already reading it for the dashboard. An interactive run keeps Ctrl+C — there it is the operator talking to this process, and a worker that ignored it would have to be killed, which abandons the task it holds. "Safer" would have been less safe.

Documentation

• Workers & daemons guide — Sizing the pool, with the five rules and what "settled" can mean.

spool:drain ran KEYS every minute, and the cache's names set never expired

Filed seven hours after an installation adopted the morning's cache work — as a follow-up, not a dispute, and it opened with the number that frames everything below:

cmdstat_scan  87,945,372  immediately after adopting the fix
cmdstat_scan  87,945,378  six hours fifty minutes later     ← six calls

Under the previous build a single process drove that counter at 2,549 calls a second. The category index reads at 1.31 µs per SMEMBERS across 4.59 million calls. What was left were two edges at the sides of it — and both are the same mistake as the one that had just been fixed, one file over.

WriteSpool::redisKeys() used KEYS, sixty times an hour

spool:drain is scheduled everyMinute, so on any installation running the framework schedule this was a blocking keyspace walk once a minute, for ever:

cmdstat_keys  calls=649  usec_per_call=8,344       ← 8.3 ms average
slowlog: 118 of 128 entries are KEYS spool:*

118 of the 128 slowest commands the server had recorded were this one call, and the slowlog was at its cap — so it had stopped saying anything about anything else. A real slow query would have had to displace a probe to be seen.

The filing offered two readings and picked the right one. SCAN … MATCH is not the substitute: MATCH filters what is returned, not what is traversed, so it trades one 8 ms stall for a walk of the whole database. A set of table names — spool:tables, written when a row is pushed — is O(tables), and it is the shape this codebase settled on for the cache's categories the same morning.

Pruned as well as written: the drain removes a table's name once its list is gone, which is the one moment that is knowable, and asked rather than assumed because a row can arrive during a drain.

And that installation's spool backend is file

So the rows never reached Redis at all. The drain probed it anyway, stalled the server for 8 ms, and got an empty list — the whole cost with none of the purpose. It does not ask now.

The check is could rows be there, not is that the configured driver: a driver changed from redis to file leaves whatever was already pushed, and refusing to look would strand it.

catnames had no expiry

SCARD catnames   5,304      TTL -1
dbsize           6,029      → the names set was 88% of the keyspace
SMEMBERS catnames  26.7 ms  → the slowest single entry in the slowlog

clearCategory() does sRem the name, so a category that is cleared leaves nothing behind. But the ordinary life of a cached read is to expire on its own TTL, and nothing clears that — so the set accumulated one member per distinct category ever cached, which on this codebase is per entity id.

The framework had already written down the shape of this in clearCategory() — "a set that never shrinks" — and the filing supplied the part that was missing, which is what it costs.

Fixed the way the per-category index sets already were: an expiry, pushed an hour past the newest member's own, so the set always outlives its members. An entry saved with no expiry keeps the set permanent, because there is then a name that will never stop being true.

Not urgent and nothing like the catindexed: problem it replaced — that was read once per save on the hot path, this when somebody opens a page — but the same shape one level up.

Two tests that passed for the wrong reason

Both spool tests were green before either fix, and the mutation check said so. In the suite, WriteSpool::redis() goes through ConnectionManager::getInstance(), which reads the framework's own Redis configuration — and that points nowhere, so every call threw Connection refused and the catch returned an empty list. "No command was sent" was true whatever the code did.

They drive a subclass whose redis() connects now, which works because redisKeys() asks static::redis(). And one assertion in the first draft compared a value with itself; it is gone.

Documentation

• Change feed guide — what the drain costs, which is nothing on a backend you do not use.
• Cache guide — the three keys table, with what bounds catnames now.

The debug-bar switch threw you to the front page, and no test could have seen why

Third report on this control, and this one came with both halves: pressing it while the bar was on did nothing, and pressing it while the bar was off did not turn it on — it threw the operator out to the front page of the site.

What it was

The switch posted its return address as an absolute URL, and returnUrl() refuses an address that is not on this site — which it must, because a redirect target arriving in a POST field is an open redirect otherwise. It checked that by comparing the value against sURL as a string prefix. Measured:

posted	compared against
http://host/devpanel	https://host	refused
https://www.host/devpanel	https://host	refused
https://host:443/devpanel	https://host	refused

Behind a proxy every one of those is ordinary — X-Forwarded-Proto, a www redirect, an explicit port. And a refused address falls back to the site root, which is exactly "it throws me to the front end of the site". The off case then looked like nothing happening for the same reason: the revocation was carried to the front page instead of back to the panel.

A path names no host, so it cannot disagree with one. That is what the switch posts now. It still has to be a path: //host/x is protocol-relative and a browser reads it as another site, /\host/x is the same trick with a backslash, and a scheme can hide after the slash — all three refused, each with a test.

Why three reports were needed to find it

Because of what the tests covered. Every test this feature had drove one request: they rendered the switch, or they posted a form the test itself had built with CsrfMiddleware::token(). That second shape is self-consistent by construction — ask the framework for a token, hand it straight back — and cannot fail.

The seam is that the token is issued while the panel renders and checked in the next request, with a session in between, and the return address makes the same trip. Nothing exercised it.

There is now a test that renders the panel, reads the hidden fields out of the HTML the way a browser reads a form, and dispatches the POST through the real controller. It covers the token round-trip, the grant being one the framework accepts, the redirect landing back on the panel, the revocation, and a form with no token being refused. Reverting the fix reddens it.

And the refusal is no longer silent

A one-line log under debug, saying what was refused and what the site is. Landing on the site root is otherwise indistinguishable from the feature being broken — which is how this was reported three times.

Behind a seam rather than a bare Logger::log(), because the first version of the test for it read the log file, which accumulates between runs: it found the string from an earlier run and passed with the reporting deleted. A seam cannot be satisfied by history.

What was checked and was not the cause

Recorded so the next report does not start here. The vendored framework on the reporting installation is byte-identical to this checkout for DebugGrantController, DevPanelController, CsrfMiddleware, Session and DebugAccess. The CSRF check is registered and does refuse a form without a token — but a 419 reaches ExceptionHandler::render() and produces an error page, not a redirect, so "thrown to the front end" was never a CSRF failure. Routing was confirmed too: POST /debugbar/enable resolves.

Documentation

• Debugging guide — the return address is a path, and why.

A redirect to HTTP_REFERER, six double decodes, and a query asked three times

Filed while tracing an SSO complaint through an application's login controller. The filing says plainly that the application's own bugs are fixed on its side and are not the filing — including one it checked and withdrew: a return value echoed into a hidden input unescaped, which turned out to be the application drifting from the framework's scaffolding views rather than a framework defect. That is the right way to file.

Application::exec() redirected to HTTP_REFERER

HTTP_REFERER is a request header. Whoever made the request picks it — so on a POST that failed validation, the sender chose where the framework sent the user.

Worse than an ordinary open redirect for two reasons the filing names. Nothing opted in: every controller that throws ValidationException reaches those two lines, so an application that has never written a redirect of its own still had this one. And the redirect carried a session it should not: the two lines above it write _validation_errors and _old_input — allCurrent(), the whole submitted request — so the user arrives at the sender's chosen destination having just posted a form, with their session holding a copy of what they typed. On a login or a payment form that is the interesting part.

A local path only, with the site root as the fallback — which is already what happens when there is no referer at all, so the failure mode is one the framework accepts.

One of the filing's five rules is deliberately not implemented, and this is the honest part. It asked to reject a : before the first /, which is what javascript: looks like. Once a leading slash is required that rule cannot help — javascript:alert(1) has no leading slash and is already refused, and /https://evil.example is resolved by a browser against this origin, so it is a path on this site. What the rule would do is refuse a legitimate path containing a colon (/media/urn:isbn:1) and send the user to the site root instead: the same silent misdirection the check exists to prevent. The CR/LF rule is implemented, and it is the one that is not merely a redirect — a newline in a Location header is response splitting.

A browser sends an absolute referer, so refusing everything that is not already a path would land every validation failure on the front page and lose the form. A same-site referer is reduced to its path, compared by origin rather than by string prefix — because sURL and the referer routinely disagree about the scheme, www, or an explicit :443 behind a proxy, and a prefix comparison refuses all three. That exact mistake is the entry above this one.

Six double decodes, not three

The filing named three and told us how to find the rest: "grep -rn 'urldecode(' src/ and, for each hit, ask where the value came from." Doing it turned up three more of the same kind:

LogController:275	filed
ApiListQuery:60, :72	filed
DevPanelController:511	the same log search, in the panel
DevPanelController:2569	a cache key from $_GET
LogViewer::setParameters()	the one place all three log callers route through

That last one is why the count matters: two of its callers decoded again before calling it, so those searches were decoded three times.

$_GET is already decoded by PHP, and a second pass turns + into a space and strips a layer, so C++ or +30 210… cannot be expressed. The {space} placeholder beside it was the tell — a caller had to write a placeholder because a real space could not survive the round trip, so the workaround and the bug were on the same line. It still works; a space is now a space.

In ApiListQuery it changed results rather than rejecting input: the values are inside a JSON object of per-field searches, and because the corruption happens before json_decode(), the JSON still parses — the caller gets a successful response with the wrong rows and nothing says so.

The four remaining urldecode() calls are correct — a raw path segment from a regex, DSN credentials from parse_url(), a token out of an email's HTML — and each now carries the one line the filing asked for, saying which kind it is, because the next reader cannot tell the two apart from the call alone.

The same query, three times, and nothing was slow

PasskeyService::activeCredentialIds() had three callers in the framework and no memoisation. Each is right to ask; none can know another already did:

0.29ms  SELECT credential_id FROM passkey_credentials WHERE userid = 2 AND is_active = true
0.13ms  SELECT credential_id FROM passkey_credentials WHERE userid = 2 AND is_active = true
0.13ms  SELECT credential_id FROM passkey_credentials WHERE userid = 2 AND is_active = true

None of them is slow, which is exactly why it survived. A tenth of a millisecond appears in no profile and neither do three of them. What made it visible was the debug toolbar listing the queries, where the same row, three times reads as a mistake in a way that 0.55 ms of total time never will.

Memoised inside the method, per instance, keyed by user id — all three choices are the filing's reasoning and all three are right. Inside, because the callers are right to ask and the next one will not know the previous asked. Per instance, because this service is constructed per use and a static would additionally need keying and invalidating across instances for no gain. Keyed, because a screen listing several accounts would otherwise report everybody's passkeys as the first user's.

array_key_exists rather than a truthiness test, because an empty list is an answer — a user with no passkeys is the common case, and [] ?: query() would re-ask for exactly those users every time. And revokeCredential()/persistCredential() forget it, with a test that reads the source, because deleting either call leaves every behavioural test green.

A claim of mine, withdrawn

While here I read a CSRF exemption leak into the framework and said so before measuring it. CsrfMiddleware::isExempt() reads the request path to decide whether a POST needs a token at all, and a test asserting that a form without a token is refused passed alone and failed beside the CSRF tests — which looked exactly like a stale path turning the check off.

It was not. Controller::_runThroughMiddleware() constructs a fresh Request before running the pipeline, and that constructor re-reads $_SERVER['REQUEST_METHOD'] — so my test, which set only the static, had its POST turned back into the GET an earlier test had left in $_SERVER. The middleware saw a safe method and passed the request through. In production $_SERVER is this request's and the middleware is right to read it. It was my test not arranging a whole request.

What stays from that detour, because it is a real improvement on its own: a Request now carries the path it was constructed for, and ownRequestUri() answers for the object with no fallback to the static — so a caller deciding policy can read an empty answer as cannot tell and take the safe branch. getRequestUri() keeps its fallback, which is the friendly behaviour for a convenience reader and the wrong one for a security gate.

Three tests were pinning the bug

Found by the full suite after the fix was pushed, which is later than it should have been: the filtered run I checked did not include the files I had changed.

ApiListQueryInputShapesTest passed urlencode('["userid","email"]') and urlencode('{"username":…}'); LogViewerTest passed hello%20world and asserted hello world with the comment "URL-encoded search term must be decoded". All three were encoding their input on purpose to satisfy the second decode — so the tests and the defect agreed with each other, and the defect looked like the contract.

They pass already-decoded values now, as $_GET delivers them, and each of the two files gained a test for what the double decode actually cost: a + in a per-field search value, and C++ in a log search. Plus one asserting {space} still works, because somebody has that string in a bookmark.

Documentation

• No guide changed: all four are defects in behaviour that the guides already describe correctly. The Request addition is documented on the method.

The test suite is three minutes; the default ./dockertest spends seven more on Xdebug

The suite had been getting slower in the way everybody assumed it would — 1,104 test files now against 445 six weeks ago, 250 of them integration. So the reported slowdown looked explained before it was measured, which is the one thing the performance page exists to warn against.

Measured instead. Same commit, same 15,693 tests, two runs minutes apart:

Run	Wall clock
./dockertest	9:50
./dockertest --nocoverage	2:56

PHPUnit's own accounting of the second run is 149.5 s across all 15,693 tests — 9.5 ms each. The tests are not slow. Xdebug is 3.3×, about 70% of the default run, because the image sets xdebug.mode=coverage and a plain run therefore instruments every line of src/ whether or not anybody opens the report. tests/Unit/Console reproduces the ratio at a smaller scale: 88 s by default, 27 s with --nocoverage.

For an ordinary run, --nocoverage. For rule 11, --coverage. The seven minutes are real either way — they are just not something a red test needs to pay for.

Documentation

• Pramnos_Test_Suite_Performance.md gains Coverage is not 12% — it is most of the run and drops the claim it replaces. The old 12% came from comparing a coverage-collecting run with one where Xdebug was still loaded in coverage mode: it measured PHPUnit's collection and report, not the instrumentation. Both the page's opening figures and its "what not to do" bullet said so, and both were wrong on the number while right on the conclusion — keep the block, use the flag.
• Roadmap.md carries the corrected reading in the testing section, and no longer dismisses the idea on the strength of 12%.

form-action 'self' cancelled every SSO login that went through the login form

An OAuth2 authorization server exists to send a user, after a form POST, to a registered third-party callback. The policy forbade exactly that, unconditionally, and no application could say otherwise.

A browser applies form-action to every redirect in the chain, not only the form's action attribute:

POST /Home/login                                  same origin   → allowed
  → 302 /oauth/authorize?…                        same origin   → allowed
  → 302 https://client.example/login-sso?code=…   other origin   → BLOCKED

Nothing on the server knows. The authorization code is generated, written, and a Location naming the client is emitted; the browser then declines to navigate. The reporting user's words were "I definitely did not receive a Location header, nor any other error" — correct from where they stood, and the opposite of what the database said: five of six codes had been redeemed, and every abandoned one had a successful retry seconds later, which is what a user does when a page does not move.

Chrome also reports the violation against the initial URL, so the console message names a same-origin address and reads as a paradox. And it is intermittent for a reason that hides it further: a user who still holds a session takes GET /oauth/authorize → 302 → client, which is not a form submission and which works. Only the attempt that passes through the login form is blocked, so the same client succeeds or fails on whether the session had expired.

Fixed

• form-action takes application sources, the way img-src already did. 'self' remains the default and should — it is the mitigation for a form injected by an XSS that would otherwise post credentials off-site. An authorization server now names its registered callbacks under csp: form-action in app.php.

Added

• frame-ancestors and frame-src are configurable too, on the same test the report proposed: whether a legitimate deployment can need another origin there. frame-ancestors has no fallback to default-src, so its hard-coded 'self' was absolute — an application embedded in a partner's portal could not be permitted to load at all. frame-src governs the mirror case, what this application may embed.
• Application::CSP_CONFIGURABLE, the framework's written claim about which directives an application can extend, with a test that asserts every entry in it actually reaches the header. That is the invariant, rather than four separate tests for four instances of one defect.
• A csp key no directive consults is now logged, once per process, naming the keys that can be set. This is the fourth time a hard-coded directive in that list has forbidden something a real deployment needed while the application's attempt to permit it was read and discarded — media-src blocked third-party audio, worker-src 'none' refused the service worker the scaffolder itself writes, then the Blob worker pf-humancheck.js builds, and now this. A configuration option that looks applied and is not is the worst shape available, and it cost a day here.

Not a refusal at boot, which is what the report asked for: the same builder runs on a page-cache hit from PageCache::serveEarly(), before there is an application to refuse on behalf of, and a site that stops serving over a stale key in app.php is a worse failure than the one being warned about. A log line is the strongest thing available in both places.

object-src 'none', base-uri 'self' and default-src 'none' stay absolute, and a test asserts they ignore configuration that asks otherwise.

Documentation

• Pramnos_Framework_Guide.md lists every configurable directive with its default and what another origin there is for, says which ones are fixed and why, and gains a section on form-action for an authorization server — including the redirect chain, because the console message alone does not lead anywhere.

The authorization endpoint redirected anywhere the request asked, with a code attached

Filed by asking the question the previous entry did not: does the framework's own OAuth server have the fault it just gave applications a way to fix?

It did, and worse than that. redirect_uri was read from the request, required to be non-empty, and then used as a redirect target — never compared against applications.callback, the registry the admin screen has been filling in all along. That is an open redirect with an authorization code attached, which is the case RFC 6749 §3.1.2 requires registration and exact matching for: a crafted authorize link sends a real code to a destination the attacker chose, and shows the user their own authorization server's login form on the way.

Fixed

• redirect_uri must be registered, and is matched exactly. Checked immediately after the client is loaded and before the user is sent anywhere, so nothing has been issued and no destination has been trusted yet. Every near miss an inexact comparison would accept is a test: a longer host, a subdomain, @ moving the authority, a different or appended path, an added query, a trailing slash, a scheme downgrade, an explicit :443, and //attacker.test.

The refusal deliberately does not echo the URI it refused — an error page that prints an attacker-controlled URL, on the authorization server's own origin, is a place to put a link.

• form-action now carries the registered callback, and only the registered one. Application::allowCspSource() widens a directive for one request; Application::cspSourceForUri() reduces a URL to the origin a policy can name — with a non-http(s) scheme contributing scheme: alone, because parse_url('myapp://oauth') reports oauth as the host, which is true of the string and useless as a policy.

The order is the whole of its safety: the check runs first, so the policy is widened to a URI the client registered, never to one the request asked for. Reversed, it turns the refusal above into a permission — and a test asserts a refused request leaves nothing behind.

The login and second-factor screens are separate requests from the endpoint that validated anything, so the verified origin travels in the session. Deriving it from ?return= instead would let a crafted return URL name any destination and be believed: the same open redirect, re-entering through the policy after being closed at the endpoint.

• The login bounce named a field the login form does not read. The endpoint sent login?return_url=…; Account::returnUrl() reads return. So the parameter arrived, was ignored, and a user who signed in there landed on the dashboard instead of back at the authorization request — a sign-in that succeeded and lost its purpose on the way, which from the client's side is indistinguishable from never getting a code.

What breaks in subclasses

Nothing. This section announced a break that was withdrawn the next day — see 8 September. It said a client with an empty callback could no longer complete an authorization request, and that there was no compatible way to keep it. Both halves were wrong: registration is the operator's decision about their own clients, and an unregistered client can be recorded and left alone rather than refused. No SQL has to be run before upgrading.

A registration that disagrees with the request is still refused, which is the registration doing its job.

Added

• Auth\Application::parseRedirectUris(), static, so the endpoint can answer is this registered from a row it already has instead of hydrating a model and querying again. getRedirectUri() and getRedirectUris() now delegate to it — two parsers for one column is how an endpoint and a repository come to disagree about what is registered. Empty entries are dropped: a callback of , used to parse into two empty strings, and an empty string matches a request that sent nothing.

What the framework already had right

issueCodeAndRedirect() ends with $this->terminate(); return; rather than exit, which is why authorize() is testable at all — the reporting application had exit in the same place, and the cost was eighty tests covering its token endpoint and none covering the branch that issues a code. Worth recording, because a filing that only lists faults teaches the wrong thing about where to look.

Documentation

• Pramnos_AuthServer_Integration_Guide.md gains The redirect URI must be registered, and matched exactly, with the five near-identical URIs that are five different registrations and why exact is the point rather than an inconvenience — plus a note on the form-action widening the server does on the client's behalf, and what its absence looks like from both sides.

An OAuth server that could not say why it refused, and a logger that never truncated

Three asks in one filing, and the third applies to every application whether or not it touches OAuth.

Fixed

• Logger::truncateLogFile() had one caller in the framework — the log viewer's manual button. So every log every application writes grew without limit, in every installation, and nobody found out until a disk did.

Logger::log() now rotates before appending: 10 MiB by default, 5 backups, and PRAMNOS_LOG_MAX_SIZE=0 disables it for an installation that already runs logrotate.

Rotating on write rather than from a scheduled sweep is deliberate. A task in FrameworkSchedule is the tidier design and only works where something actually runs schedule:run — the installation that reported this had the scheduler unrun for the life of the project. A framework default has to hold where nothing was set up, and the cost in the common case is one stat and a return.

• The rotation notice went into the wrong file. truncateLogFile() announced itself through notice() without passing the file name, so rotating oauth.log wrote the announcement into pramnosframework.log — the one place nobody looks when asking why a log starts where it does.

Added

• Auth\Controllers\Oauth writes down what it decided. It had one Logger::log call and it was about a session that would not close during logout. The endpoint can end a request four ways without the client getting a code — the token endpoint refusing, the consent form being shown, the user denying, a parameter being rejected — and recorded none of them. Measured on one installation in one day: 23 responses of 4xx from the token endpoint, and not one explainable afterwards. Diagnosing a single failure came down to comparing the byte counts of two 302s in an access log, which is arithmetic with a hypothesis attached.

The line carries the inputs, not only the outcome, because the reports worth investigating are the ones where the request looked fine.

Never a credential — not a code, an access or refresh token, a client_secret or a code_verifier. The line is built from a fixed list of keys rather than filtered against a list of forbidden ones, so the next call site cannot leak one by not knowing the rule.

Two chokepoints instead of nineteen call sites, and that is the filing's own warning taken literally: "Every exit from a decision needs the line, not the one that looks like the exit." Every JSON answer this controller gives goes through respondJson(), and every response the League server produces — refusals included, since OAuthServerException::generateHttpResponse() is emitted the same way as a successful grant — goes through emitPsrResponse(). There is no site left to miss.

• The successful half is behind oauth_decision_log, default off. An issued code or token is logged only when that setting is truthy. usertokens already holds the row with its timestamp, user, application and scope, and user_activity_log already holds application_authorized; a user id and a destination per sign-in kept for ever is a retention decision rather than a diagnostic — and it should be one somebody made.

Read forced on every request, so flipping it takes effect on the next request rather than whenever a cache expires. A switch nobody can see take effect is a switch nobody trusts. No interface work was needed: a scaffolded application's settings screen already edits the table generically.

logDecision(), respondJson(), logTokenEndpointOutcome() and decisionLogIsVerbose() are protected, so an application shipping logs somewhere structured overrides one method rather than four call sites.

Where a test is honest about what it does not prove

rotateIfNeeded() has a re-entry guard, and removing it reddens nothing: rotation's own notice comes back through log(), but truncateLogFile() has renamed the file away by then, so the is_file() check is what actually stops the recursion. The guard stays and says so — otherwise the only thing preventing unbounded recursion is the statement order inside another method, and the symptom of getting that wrong is a stack overflow rather than a log line.

Documentation

• Pramnos_Logging_Guide.md — File Rotation now leads with the automatic behaviour and the two environment variables, says when to set the cap to 0, and keeps truncateLogFile() for an explicit rotation.
• Pramnos_AuthServer_Integration_Guide.md gains When a sign-in fails: the decision log — the lines it writes, the guarantee that no credential is among them, and the table of what the setting changes.

The debug switch said it was enabled and no Set-Cookie ever went out

Fourth report on this switch, and the first three fixes were all about the return address — styling, the CSRF registration, then the path-versus-URL comparison behind a proxy. Each was a real defect. None of them was this one, and the reason they were not is worth writing down: the reports said "it does nothing", so each round looked for the place the click was being lost. The click was arriving.

"It says it was enabled but it does not work. Only the console enables it properly."

The fault

?_debug=<token> becomes a cookie inside DebugAccess::isGranted() — that is the only place setCookie() is reached. The switch returns to the DevPanel, which echoes its own HTML and reads the grant's state with expiresAt(). That verifies the offered token and reports its expiry without persisting anything.

So the panel drew the switch as on, correctly: the grant was real, for that one request. No Set-Cookie header was ever sent. The next ordinary page had nothing. And the console works because debug:token prints a URL you open on an ordinary page — which renders through the framework, which calls isGranted().

postDisable() had the mirror of it: it redirected with ?_debug=off and left the clearing to the landing page, so turning the toolbar off from the panel reported success and left it on everywhere else.

Fixed

• DebugAccess::establish() and DebugAccess::revoke(), called from postEnable() and postDisable() before their redirects. Whoever issues a grant establishes it rather than hoping the next page will. ?_debug= stays on the redirect — it costs nothing and covers the first page if the cookie is refused — but nothing depends on it any more.

establish() verifies before it writes. It is a public method that sets the cookie the whole guard rests on, and one that would accept any string is one call away from being the way in.

• The DevPanel persists an offered token when it reads the state. It is also the page a developer pastes a debug:token URL onto while already looking at it, which was the same report arriving from the other direction.

Why the tests passed through all four rounds

Every test this feature had simulated the browser following the redirect and then called isGranted() — the one call that was missing in production. So they asserted "the redirect carries a token that verifies", which was true the whole time, rather than "the grant survives the request that issued it", which was not.

Three tests now assert the second thing, with no ?_debug= in sight, and each of the three fixes above reddens exactly one of them.

Documentation

• Pramnos_Debugging_Guide.md — Opening the toolbar on a live server now says the grant is established on the response that issues it, and explains the expiresAt() versus isGranted() distinction that produced four reports, since a developer page reading the state is where it bites.