From 232b95d40decb0fe360ec527b1ca0fbb15290267 Mon Sep 17 00:00:00 2001 From: Akihito Koriyama Date: Tue, 18 Aug 2026 04:45:03 +0900 Subject: [PATCH 1/5] Name the store when it is the thing that failed `symfony/cache` adapters never throw at the application: an unreachable store answers a read as a miss and a write as `false`. So `guard()` catches nothing, no `cache_error` is recorded, and a Redis restart reads as a run of ordinary cold reads - the one shape an operator cannot act on. The write side at least said `saved: false`; the read side said nothing at all. The adapters report those failures to a PSR-3 logger, so the pools are handed the cache log: `pool_error{key, operation, error, exceptionClass}` carries the backend's own message beside the miss it caused. Wired where the pools are built (Redis and Memcached), demonstrated against a real adapter pointed at a closed port, and distinguished from `cache_error` in both guides - that one is an exception this package caught, with the resource URI in hand. Found by an application flow that pointed the DSN at a dead port and asked what the log said. --- CHANGELOG.md | 1 + demo/run-degraded.php | 34 ++++++++++ docs/reading-the-log.ja.md | 7 ++ docs/reading-the-log.md | 7 ++ docs/schemas/context/pool_error.json | 32 +++++++++ docs/what-the-log-proves.ja.md | 1 + docs/what-the-log-proves.md | 1 + src/Log/Context/PoolErrorContext.php | 30 +++++++++ src/Log/PoolErrorLogger.php | 82 +++++++++++++++++++++++ src/StorageMemcachedModule.php | 13 +++- src/StorageRedisDsnModule.php | 7 ++ tests/PoolErrorLogTest.php | 97 ++++++++++++++++++++++++++++ 12 files changed, 311 insertions(+), 1 deletion(-) create mode 100644 docs/schemas/context/pool_error.json create mode 100644 src/Log/Context/PoolErrorContext.php create mode 100644 src/Log/PoolErrorLogger.php create mode 100644 tests/PoolErrorLogTest.php diff --git a/CHANGELOG.md b/CHANGELOG.md index 7480b18b..a0f0f138 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -39,6 +39,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - Japanese versions of the three human-facing documents, beside their English originals under the convention the repository already uses for `README.ja.md`: `docs/reading-the-log.ja.md`, `docs/why-the-log-records-everything.ja.md`, `docs/what-the-log-proves.ja.md`. The published paths stay where they are - `docs/schemas/context/*.json` is embedded in every entry's `schemaUrl` and `docs/llms*.txt` is served at a well-known path, so neither moves for a language split. `ReadingGuideCoverageTest` now runs against both guides, so a new context type or enum value fails until it is explained in each. - `docs/reading-the-log.md`: the reader's guide to the log - the tree grammar (open / event / close), every one of the 26 context types with its fields, every outcome word with what it means, the reading rules that cannot be guessed from a field name (marker-preceded cleanup, degraded vs cold, the 304 shape, tag intersection), a Terminology table that expands the names the log uses for its own parts (`roPool` is the pool bound with `#[ResourceObjectPool]`, `tags` are surrogate keys, `layer` is which store answered rather than which pool was written) and points at the manual for the concepts, and a worked session taken verbatim from a demo. `ReadingGuideCoverageTest` fails if a context type or a schema enum value is not accounted for there, so a published word cannot ship without an explanation. Linked from both READMEs; `docs/llms.txt`/`llms-full.txt` keep the same facts in lookup form and point at it. - `cache_policy`: what a resource declared about its lifetime, recorded where the `#[Cacheable]` declaration is read. Exactly one of `expiry` / `expirySecond` / `expiryAt` is non-null - the one that decided - beside the `resolvedTtl` it produced. A TTL alone cannot say whether an entry is meant to expire: the `never` preset resolves to a finite number an application can rebind through `Expiry`, so an event-driven entry and a deliberate 1-year TTL used to log the same lifetime (#186). +- `pool_error`: the cache backend's own report of an operation it refused. `symfony/cache` adapters do not throw at the application - an unreachable store answers a read as a miss and a write as `false` - so a dead store used to be indistinguishable from a cold one on the read side. The pools are now given the cache log through a PSR-3 adapter, so the store that failed is named where every other cache decision already is. - `Exception\UnsupportedLogStream`: `LogStreamWriter` accepts a filesystem path or `php://stdout|stderr|output` and rejects any other wrapper, so a module argument cannot truncate an unrelated file through `php://filter/…` or ship every session to an `ftp://` host. Writes now take an exclusive lock (`flock`) instead of relying on `file_put_contents` flags, which the default `php://stdout` target silently dropped - concurrent workers could interleave half-lines in the JSONL a collector parses. - `PsrLogWriter`: sends a kept session to the application's PSR-3 logger (already in every BEAR app's tree via bear/sunday and bear/resource), passing the tree as structured context under `log` rather than as a message. It is an adapter behind `LogWriterInterface`, not a replacement for it: PSR-3 carries strings, and its level would be a second filter that can drop what the retention policy kept. - `ConcurrentRuntimeInterface`/`HostRuntime`: where the sink can prove the host is concurrent (`RR_MODE` set, or inside a Swoole coroutine) it refuses to arm, reports through `error_log()` and **recording stops with it** - `SafeSemanticLogger` falls back to the no-op logger, since an unarmed sink leaves nothing that would ever drain the session. Mode is consulted, never capability (a loaded ext-swoole proves nothing about how the app is served), and the two checks are explicitly not an exhaustive account: a Swoole worker whose logger is built outside a coroutine, FrankenPHP worker mode, ReactPHP, Amp and a long-lived CLI consumer are not detected and must bind their own implementation. Diagnostics use `error_log()` rather than `trigger_error()` because arming happens while the injector builds the logger, where a strict error handler would turn a warning into a boot failure on exactly those hosts. diff --git a/demo/run-degraded.php b/demo/run-degraded.php index 67bd05a3..753c4b05 100644 --- a/demo/run-degraded.php +++ b/demo/run-degraded.php @@ -43,6 +43,7 @@ use BEAR\QueryRepository\Cdn\AkamaiModule; use BEAR\QueryRepository\DonutRepositoryInterface; +use BEAR\QueryRepository\Log\PoolErrorLogger; use BEAR\QueryRepository\FakeErrorCache; use BEAR\QueryRepository\FakeEtagPoolModule; use BEAR\QueryRepository\FakeRefusingPool; @@ -61,9 +62,13 @@ use Koriym\SemanticLogger\Stree\RenderConfig; use Koriym\SemanticLogger\Stree\TreeRenderer; use Madapaja\TwigModule\TwigModule; +use Psr\Log\LoggerInterface; +use Ray\Di\InjectionPoints; use Ray\Di\AbstractModule; use Ray\Di\Injector; use Symfony\Component\Cache\Adapter\ArrayAdapter; +use Symfony\Component\Cache\Adapter\RedisAdapter; +use Symfony\Component\Cache\Adapter\RedisTagAwareAdapter; use Symfony\Component\Cache\Adapter\TagAwareAdapter; use Symfony\Component\Cache\Adapter\TagAwareAdapterInterface; @@ -409,3 +414,32 @@ protected function configure(): void echo ' and the whole write is rooted in manual_store{,_result} — cleanup invalidate included' . PHP_EOL; $report($logger->flush(), 'I. donut write through the repository API'); + +// ------------------------------------------- J. the store is down, and says so +// symfony/cache adapters do not throw: a store that cannot be reached answers a read as a miss +// and a write as false, so session B's outage - an adapter that throws - is not what production +// looks like. A real RedisAdapter pointed at a closed port is, and what makes it visible is the +// PSR-3 logger the pool reports to. +$injector = $newInjector(new class extends AbstractModule { + protected function configure(): void + { + $this->bind(LoggerInterface::class)->annotatedWith('poolError')->to(PoolErrorLogger::class); + $this->bind(TagAwareAdapterInterface::class) + ->annotatedWith(ResourceObjectPool::class) + ->toConstructor( + RedisTagAwareAdapter::class, + ['redis' => 'deadRedis'], + (new InjectionPoints())->addMethod('setLogger', 'poolError'), + ); + $this->bind()->annotatedWith('deadRedis')->toInstance(RedisAdapter::createConnection('redis://127.0.0.1:1')); + } +}); +$resource = $injector->getInstance(ResourceInterface::class); +$logger = $injector->getInstance(SemanticLoggerInterface::class, CacheLog::class); + +$ro = $resource->get('app://self/value'); +echo sprintf('J GET app://self/value -> %d served live while the store is unreachable:', $ro->code) . PHP_EOL; +echo ' pool_error{read} for the lookup and pool_error{write} for the store, with the' . PHP_EOL; +echo ' backend\'s own message - without them the miss reads exactly like a cold one' . PHP_EOL; + +$report($logger->flush(), 'J. the store is down and says so'); diff --git a/docs/reading-the-log.ja.md b/docs/reading-the-log.ja.md index 65e5694d..180a1e0c 100644 --- a/docs/reading-the-log.ja.md +++ b/docs/reading-the-log.ja.md @@ -102,6 +102,7 @@ get page://self/html/blog-posting ← スコープ: open されて clos | `put_skipped` | `uri`, `reason`, `code` | miss の後に書き込みを**しなかった**ことと、その理由 | | `cache_hit` / `cache_miss` | `layer` | 内側の照会。必ず `layer: donut` — donut テンプレートがあったか | | `cache_error` | `uri`, `operation`, `error`, `exceptionClass` | キャッシュ経路が throw した | +| `pool_error` | `key`, `operation`, `error`, `exceptionClass` | バックエンドが操作を拒み、アダプタが握り潰した | | `semantic_logger_error` | `kind`, `message`, … | ロガー自体の誤用(コア側の診断で、このパッケージの語彙ではない) | ## 結果が入るフィールド @@ -160,6 +161,12 @@ get page://self/html/blog-posting ← スコープ: open されて clos どう束縛したかで変わります — 既定のインストールでは `never` が 31536000 秒になり、意図的な 1 年 TTL と まったく同じに見えます。`expirySecond` か `expiryAt` が non-null 側なら、そのエントリは期限切れになり、 どの宣言が決めたかも分かります。 +**`pool_error` はストアそのもの、`cache_error` はこのパッケージが捕まえた例外です。** +`symfony/cache` のアダプタはアプリに向けて throw しません。到達できないストアは read には miss、 +write には `false` を返すので、`cache_error` を生む `catch` には何も届きません。アダプタは代わりに +失敗を PSR-3 ロガーへ報告し、プールにはキャッシュログが渡されています — だからストアが落ちているとき、 +miss の隣に `pool_error` が並びます(沈黙にはなりません)。そこで分かるのはプールのキーだけで、 +リソース URI ではありません。 **`cdn_headers` に出るのは、応答に実際に付いたヘッダです。** CDN モジュールの暗黙の既定値も含みます。 lifetime ヘッダの無いマップは、CDN に lifetime 指示を与えなかった応答です。`surrogateKeys` と diff --git a/docs/reading-the-log.md b/docs/reading-the-log.md index 154b094b..a5e3acf3 100644 --- a/docs/reading-the-log.md +++ b/docs/reading-the-log.md @@ -104,6 +104,7 @@ operation inside a GET or a command is an ordinary event there instead. | `put_skipped` | `uri`, `reason`, `code` | a miss was **not** followed by a write, and why | | `cache_hit` / `cache_miss` | `layer` | an inner lookup, always `layer: donut` — whether the donut template was there | | `cache_error` | `uri`, `operation`, `error`, `exceptionClass` | the cache path threw | +| `pool_error` | `key`, `operation`, `error`, `exceptionClass` | the backend refused an operation and the adapter swallowed it | | `semantic_logger_error` | `kind`, `message`, … | the logger itself was misused (core diagnostic, not this package's vocabulary) | ## Outcome fields @@ -163,6 +164,12 @@ which is what serving stale looks like from the inside. how the application bound `Expiry` — a default install turns `never` into 31536000 seconds, which reads exactly like a deliberate 1-year TTL. `expirySecond` or `expiryAt` being the non-null one means the entry expires, and says who decided. +**A `pool_error` is the store itself; a `cache_error` is an exception this package caught.** +`symfony/cache` adapters never throw at the application: an unreachable store answers a read as a +miss and a write as `false`, so nothing reaches the `catch` that produces a `cache_error`. The +adapter reports the failure to a PSR-3 logger instead, and the pools are given the cache log - so +a store that is down is a run of `pool_error` beside the misses, not silence. Only the pool key is +known there, not the resource URI. **`cdn_headers` shows what the response really carried**, including a CDN module's silent default. A map with no lifetime header is a response that gave the CDN no lifetime directive. diff --git a/docs/schemas/context/pool_error.json b/docs/schemas/context/pool_error.json new file mode 100644 index 00000000..79715588 --- /dev/null +++ b/docs/schemas/context/pool_error.json @@ -0,0 +1,32 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/pool_error.json", + "title": "pool_error", + "description": "Event: the cache backend refused an operation and the adapter swallowed it. `symfony/cache` never throws at the application - a store that cannot be reached answers a read as a miss and a write as `false` - so a dead store reads exactly like a cold one unless the adapter's own report is recorded. Distinct from `cache_error`, which is an exception this package caught with the resource URI in hand; here only the pool key is known.", + "type": "object", + "required": [ + "key", + "operation", + "error", + "exceptionClass" + ], + "properties": { + "key": { + "description": "the pool key the adapter was working on, empty when it did not name one", + "type": "string" + }, + "operation": { + "description": "which side refused, as the adapter worded it: `read`, `write`, or `unknown` when the wording is not one this package recognises - a mislabelled side is worse than an unlabelled one", + "type": "string" + }, + "error": { + "description": "the backend's message", + "type": "string" + }, + "exceptionClass": { + "description": "the throwable the adapter caught, or `unknown` when it reported no exception", + "type": "string" + } + }, + "additionalProperties": false +} diff --git a/docs/what-the-log-proves.ja.md b/docs/what-the-log-proves.ja.md index 874e1f4e..82707ebb 100644 --- a/docs/what-the-log-proves.ja.md +++ b/docs/what-the-log-proves.ja.md @@ -15,6 +15,7 @@ | 5 | なぜエントリがないのか — 何も保存されていなかったのか(コールド)、それともストアが読めなかったのか(縮退: フレームワークがキャッシュ無しとして振る舞い、リソースを走らせた)？ | `put_skipped` `{reason, code}`、`cache_error` `{operation, exceptionClass}` — `operation: read` が、それでも閉じる `cache_miss` と対になっているものが縮退した読み取り | スキップ理由、失敗した側（`read`/`write`）、throwable のクラスがピン留めされている。`cache_error{read}` + `cache_miss` = 縮退した読み取り、`cache_miss` 単独 = cold | | 6 | この書き込みまたは無効化を始めたのは誰か — フレームワークか、アプリケーションか？ | `command` スコープは生成元のインターセプター（`source`）を名指す。直接呼び出しは `manual_store` / `manual_purge` / `manual_invalidate` を根とし、結果は close 側に載る。`pre_write_cleanup` は writer 自身のクリーンアップを示す | 例外を投げる書き込みは `manual_store_result{failed}` で閉じる。呼び出し側が例外を捕まえているのにスコープが `stored` で閉じるのはログが嘘をついている状態であり、テストがそれを禁じる | | 7 | このエントリは期限切れになる設計か、それとも何かが無効化するまで生きる設計か? | `cache_policy` `{expiry, expirySecond, expiryAt, resolvedTtl}` — `#[Cacheable]` の宣言を読む場所で記録 | 3 つの宣言のうち non-null は 1 つだけ、それが決めたもの。TTL ではこれに答えられない — `never` プリセットはアプリが再束縛できる有限の数値に解決するので、イベント駆動のエントリと意図的な 1 年 TTL が同じ寿命として記録される | +| 8 | ストアは応答しているのか、それとも miss はすべて障害なのか? | `pool_error` `{key, operation, error, exceptionClass}` — 拒んだバックエンドについてのアダプタ自身の報告 | `symfony/cache` はアプリに throw しないので、プールにキャッシュログを渡している。死んだストアからの read は他と同じ miss であり、隣の `pool_error` が「落ちている」と「冷たい」を分ける。実際の Redis アダプタを閉じたポートに向けて実演 | ## 強制の層 diff --git a/docs/what-the-log-proves.md b/docs/what-the-log-proves.md index 99912039..360b87e6 100644 --- a/docs/what-the-log-proves.md +++ b/docs/what-the-log-proves.md @@ -22,6 +22,7 @@ is removed or its meaning inverted (verified by mutation testing). | 5 | Why is there no entry — was nothing stored (cold), or could the store not be read (degraded: the framework ran the resource as if there were no cache)? | `put_skipped` `{reason, code}`, `cache_error` `{operation, exceptionClass}` — `operation: read` paired with the still-closing `cache_miss` is a degraded read | Skip reasons, the failing side (`read`/`write`) and the throwable class are pinned; `cache_error{read}` + `cache_miss` = degraded read, lone `cache_miss` = cold | | 6 | Who initiated this write or invalidation — the framework or the application? | `command` scopes name their producing interceptor (`source`); direct calls root in `manual_store` / `manual_purge` / `manual_invalidate` with the outcome on the close; `pre_write_cleanup` marks a writer's own cleanup | A write that throws closes `manual_store_result{failed}` — a scope closing `stored` while the caller catches an exception is the log lying, and a test forbids it | | 7 | Is this entry meant to expire, or to live until something invalidates it? | `cache_policy` `{expiry, expirySecond, expiryAt, resolvedTtl}` — recorded where the `#[Cacheable]` declaration is read | Exactly one of the three declarations is non-null: the one that decided. A TTL cannot answer this — the `never` preset resolves to a finite number an application can rebind, so an event-driven entry and a deliberate 1-year TTL log the same lifetime | +| 8 | Is the store answering, or is every miss really an outage? | `pool_error` `{key, operation, error, exceptionClass}` - the adapter's own report of a backend that refused | `symfony/cache` never throws at the application, so the pools are given the cache log: a read from a dead store is a miss like any other, and the `pool_error` beside it is what separates down from cold. Demonstrated against a real Redis adapter pointed at a closed port | ## The enforcement layers diff --git a/src/Log/Context/PoolErrorContext.php b/src/Log/Context/PoolErrorContext.php new file mode 100644 index 00000000..e7c42675 --- /dev/null +++ b/src/Log/Context/PoolErrorContext.php @@ -0,0 +1,30 @@ +logger->event(new PoolErrorContext( + isset($context['key']) ? (string) $context['key'] : '', + $this->operation((string) $message), + $exception instanceof Throwable ? $exception->getMessage() : (string) $message, + $exception instanceof Throwable ? $exception::class : 'unknown', + )); + } + + /** + * Which side of the pool refused, as the adapter worded it. + * + * `unknown` rather than a guess: the wording belongs to `symfony/cache`, and a reader + * aggregating write failures should not be handed a read that was mislabelled. + * + * @return 'read'|'write'|'unknown' + */ + private function operation(string $message): string + { + if (str_contains($message, 'fetch') || str_contains($message, 'read')) { + return 'read'; + } + + foreach (['save', 'write', 'delete', 'unlink', 'invalidate', 'clear', 'prune'] as $word) { + if (str_contains($message, $word)) { + return 'write'; + } + } + + return 'unknown'; + } +} diff --git a/src/StorageMemcachedModule.php b/src/StorageMemcachedModule.php index f6310746..e2ed27f3 100644 --- a/src/StorageMemcachedModule.php +++ b/src/StorageMemcachedModule.php @@ -4,10 +4,13 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\PoolErrorLogger; use BEAR\RepositoryModule\Annotation\ResourceObjectPool; use BEAR\RepositoryModule\Annotation\TagsPool; use Override; +use Psr\Log\LoggerInterface; use Ray\Di\AbstractModule; +use Ray\Di\InjectionPoints; use Ray\PsrCacheModule\Annotation\CacheNamespace; use Ray\PsrCacheModule\MemcachedAdapter; use Ray\PsrCacheModule\Psr6MemcachedModule; @@ -31,7 +34,14 @@ public function __construct( #[Override] protected function configure(): void { - $this->bind(AdapterInterface::class)->annotatedWith(ResourceObjectPool::class)->to(MemcachedAdapter::class); + $this->bind(LoggerInterface::class)->annotatedWith('poolError')->to(PoolErrorLogger::class); + $this->bind(AdapterInterface::class)->annotatedWith(ResourceObjectPool::class)->toConstructor( + MemcachedAdapter::class, + [], + // Memcached swallows backend failures the same way Redis does: without the cache log + // in the adapter's hands, a store that is down is a run of ordinary misses. + (new InjectionPoints())->addMethod('setLogger', 'poolError'), + ); $this->install(new Psr6MemcachedModule($this->servers)); $this->bind(TagAwareAdapterInterface::class)->annotatedWith(ResourceObjectPool::class)->toConstructor( TagAwareAdapter::class, @@ -40,6 +50,7 @@ protected function configure(): void 'tagsPool' => TagsPool::class, 'namespace' => CacheNamespace::class, ], + (new InjectionPoints())->addMethod('setLogger', 'poolError'), ); } } diff --git a/src/StorageRedisDsnModule.php b/src/StorageRedisDsnModule.php index 246e505f..d545204f 100644 --- a/src/StorageRedisDsnModule.php +++ b/src/StorageRedisDsnModule.php @@ -4,12 +4,15 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\PoolErrorLogger; use BEAR\RepositoryModule\Annotation\MarshallerOptions; use BEAR\RepositoryModule\Annotation\RedisDsn; use BEAR\RepositoryModule\Annotation\RedisDsnOptions; use BEAR\RepositoryModule\Annotation\ResourceObjectPool; use Override; +use Psr\Log\LoggerInterface; use Ray\Di\AbstractModule; +use Ray\Di\InjectionPoints; use Ray\Di\ProviderInterface; use Ray\PsrCacheModule\Annotation\CacheNamespace; use ReflectionException; @@ -85,6 +88,7 @@ protected function configure(): void $this->bind()->annotatedWith('defaultLifetime')->toInstance($this->defaultLifetime); $this->bind(ProviderInterface::class)->annotatedWith('marshaller')->to(MarshallerProvider::class); $this->bind(MarshallerInterface::class)->annotatedWith('marshaller')->toProvider(MarshallerProvider::class); + $this->bind(LoggerInterface::class)->annotatedWith('poolError')->to(PoolErrorLogger::class); $this->bind(TagAwareAdapterInterface::class)->annotatedWith(ResourceObjectPool::class)->toConstructor( RedisTagAwareAdapter::class, [ @@ -93,6 +97,9 @@ protected function configure(): void 'defaultLifetime' => 'defaultLifetime', 'marshaller' => 'marshaller', ], + // The adapter reports backend failures to a PSR-3 logger instead of throwing, so the + // cache log is given to it: without this a store that is down looks like a cold one. + (new InjectionPoints())->addMethod('setLogger', 'poolError'), ); } } diff --git a/tests/PoolErrorLogTest.php b/tests/PoolErrorLogTest.php new file mode 100644 index 00000000..e3b4b8d5 --- /dev/null +++ b/tests/PoolErrorLogTest.php @@ -0,0 +1,97 @@ +bind(LoggerInterface::class)->annotatedWith('poolError')->to(PoolErrorLogger::class); + $this->bind()->annotatedWith('deadRedis')->toInstance(RedisAdapter::createConnection('redis://127.0.0.1:1')); + $this->bind(TagAwareAdapterInterface::class)->annotatedWith(ResourceObjectPool::class)->toConstructor( + RedisTagAwareAdapter::class, + ['redis' => 'deadRedis'], + (new InjectionPoints())->addMethod('setLogger', 'poolError'), + ); + } + }; + $injector = new Injector($module, __DIR__ . '/tmp'); + $this->resource = $injector->getInstance(ResourceInterface::class); + $this->logger = $injector->getInstance(SemanticLoggerInterface::class, CacheLog::class); + + parent::setUp(); + } + + public function testTheRequestIsServedAndTheStoreIsNamedAsWhatFailed(): void + { + $ro = $this->resource->get('app://self/value'); + + $this->assertSame(200, $ro->code, 'a cache that cannot be reached costs latency, not the response'); + + $tree = $this->flushAndValidate($this->logger); + $types = self::collectTypes($tree); + + $this->assertContains('pool_error', $types, 'the store refused and the log has to say so'); + // The read is what a request hits first, and it is the half that has no other signal: + // a write at least reports saved: false. + $this->assertStringContainsString('"operation":"read"', (string) self::eventContextJsonOf($tree, 'pool_error')); + } + + public function testTheBackendsOwnMessageIsCarried(): void + { + $this->resource->get('app://self/value'); + + $context = (string) self::eventContextJsonOf($this->flushAndValidate($this->logger), 'pool_error'); + + $this->assertTrue(str_contains($context, 'Connection refused'), $context); + $this->assertStringContainsString('ConnectionException', $context, 'the throwable the adapter caught'); + } + + public function testAMissIsStillRecordedSoTheReadPathIsNotSilent(): void + { + // The miss is not a lie - there is no entry - but on its own it reads as cold. The pair is + // the diagnosis: a miss beside a pool_error is a store that is down. + $this->resource->get('app://self/value'); + + $types = self::collectTypes($this->flushAndValidate($this->logger)); + + $this->assertContains('cache_miss', $types); + $this->assertContains('pool_error', $types); + } +} From fc3049159e6a6c81997d76a03f568ae0f28567d6 Mon Sep 17 00:00:00 2001 From: Akihito Koriyama Date: Tue, 18 Aug 2026 13:01:20 +0900 Subject: [PATCH 2/5] Say where a command annotation stops reaching `#[Refresh]` and `#[Purge]` carry a URI. A resource whose entries share one invalidation handle - a corpus tag across every query string that produced an entry - cannot be expressed that way, and a write that does not happen inside a resource method has no interceptor at all. Both cases end at `invalidateTags()`, which is why the log roots a direct call in `manual_invalidate` instead of dropping its events. Written where a reader looks when the cache misbehaves, not in the attribute that already types its argument as a URI. --- docs/reading-the-log.ja.md | 6 ++++++ docs/reading-the-log.md | 7 +++++++ 2 files changed, 13 insertions(+) diff --git a/docs/reading-the-log.ja.md b/docs/reading-the-log.ja.md index 180a1e0c..e5f26cd9 100644 --- a/docs/reading-the-log.ja.md +++ b/docs/reading-the-log.ja.md @@ -161,6 +161,12 @@ get page://self/html/blog-posting ← スコープ: open されて clos どう束縛したかで変わります — 既定のインストールでは `never` が 31536000 秒になり、意図的な 1 年 TTL と まったく同じに見えます。`expirySecond` か `expiryAt` が non-null 側なら、そのエントリは期限切れになり、 どの宣言が決めたかも分かります。 +**コマンド注釈が届くのは URI で、タグではありません。** `#[Refresh]` と `#[Purge]` が持つのは URI です。 +エントリ群が 1 つの無効化ハンドル(エントリを生んだクエリ文字列すべてに渡る corpus タグ)を共有している +リソースは `invalidateTags()` を呼んで無効化し、それは `command` スコープの中ではなく `manual_invalidate` +として現れます。リソースメソッドの外で起きる書き込みにはインターセプタが一切かかりません。その形では +直接呼び出しが唯一の道であり、manual スコープがそのイベントを見える場所に留めています。 + **`pool_error` はストアそのもの、`cache_error` はこのパッケージが捕まえた例外です。** `symfony/cache` のアダプタはアプリに向けて throw しません。到達できないストアは read には miss、 write には `false` を返すので、`cache_error` を生む `catch` には何も届きません。アダプタは代わりに diff --git a/docs/reading-the-log.md b/docs/reading-the-log.md index a5e3acf3..686690b7 100644 --- a/docs/reading-the-log.md +++ b/docs/reading-the-log.md @@ -164,6 +164,13 @@ which is what serving stale looks like from the inside. how the application bound `Expiry` — a default install turns `never` into 31536000 seconds, which reads exactly like a deliberate 1-year TTL. `expirySecond` or `expiryAt` being the non-null one means the entry expires, and says who decided. +**A command annotation reaches a URI, not a tag.** `#[Refresh]` and `#[Purge]` carry a URI, so a +resource whose entries share one invalidation handle - a corpus tag across every query string that +produced an entry - is invalidated by calling `invalidateTags()`, which appears as +`manual_invalidate` rather than inside a `command` scope. A write outside a resource method has no +interceptor at all: in that shape the direct call is the only path, and the manual scope is what +keeps its events visible. + **A `pool_error` is the store itself; a `cache_error` is an exception this package caught.** `symfony/cache` adapters never throw at the application: an unreachable store answers a read as a miss and a write as `false`, so nothing reaches the `catch` that produces a `cache_error`. The From ecc5d0a0cc377a29516d04c3cdc9c43c6e05e3fc Mon Sep 17 00:00:00 2001 From: Akihito Koriyama Date: Wed, 19 Aug 2026 17:37:45 +0900 Subject: [PATCH 3/5] Make the dead-store probes work with ext-redis, and satisfy PHPStan The closed-port probes connected eagerly under ext-redis (Predis is lazy by default), so the InvalidArgumentException escaped at configure time instead of surfacing as pool_error events at run time - every ubuntu CI job runs with ext-redis loaded and failed at PoolErrorLogTest:46. Pass lazy=1 in the DSN so both backends defer the connection. testTheBackendsOwnMessageIsCarried pinned the Predis exception class (ConnectionException); ext-redis surfaces the adapter's InvalidArgumentException. The contract is that the caught throwable's class is carried, so assert exceptionClass is not 'unknown'. PoolErrorLogger: guard the mixed $level/$key casts PHPStan flagged. --- demo/run-degraded.php | 4 +++- src/Log/PoolErrorLogger.php | 7 +++++-- tests/PoolErrorLogTest.php | 6 ++++-- 3 files changed, 12 insertions(+), 5 deletions(-) diff --git a/demo/run-degraded.php b/demo/run-degraded.php index 753c4b05..3c768b50 100644 --- a/demo/run-degraded.php +++ b/demo/run-degraded.php @@ -431,7 +431,9 @@ protected function configure(): void ['redis' => 'deadRedis'], (new InjectionPoints())->addMethod('setLogger', 'poolError'), ); - $this->bind()->annotatedWith('deadRedis')->toInstance(RedisAdapter::createConnection('redis://127.0.0.1:1')); + // lazy=1: with ext-redis the default is an eager connect, and a boot-time throw is not + // the runtime outage this session demonstrates (Predis is lazy by default). + $this->bind()->annotatedWith('deadRedis')->toInstance(RedisAdapter::createConnection('redis://127.0.0.1:1?lazy=1')); } }); $resource = $injector->getInstance(ResourceInterface::class); diff --git a/src/Log/PoolErrorLogger.php b/src/Log/PoolErrorLogger.php index eafaf3f2..056a9a84 100644 --- a/src/Log/PoolErrorLogger.php +++ b/src/Log/PoolErrorLogger.php @@ -14,6 +14,7 @@ use Throwable; use function in_array; +use function is_string; use function str_contains; /** @@ -42,15 +43,17 @@ public function __construct( #[Override] public function log($level, string|Stringable $message, array $context = []): void { - if (! in_array((string) $level, self::FAILED, true)) { + if (! is_string($level) || ! in_array($level, self::FAILED, true)) { return; } /** @var mixed $exception */ $exception = $context['exception'] ?? null; + /** @var mixed $key */ + $key = $context['key'] ?? ''; $this->logger->event(new PoolErrorContext( - isset($context['key']) ? (string) $context['key'] : '', + is_string($key) ? $key : '', $this->operation((string) $message), $exception instanceof Throwable ? $exception->getMessage() : (string) $message, $exception instanceof Throwable ? $exception::class : 'unknown', diff --git a/tests/PoolErrorLogTest.php b/tests/PoolErrorLogTest.php index e3b4b8d5..14445317 100644 --- a/tests/PoolErrorLogTest.php +++ b/tests/PoolErrorLogTest.php @@ -43,7 +43,9 @@ protected function setUp(): void protected function configure(): void { $this->bind(LoggerInterface::class)->annotatedWith('poolError')->to(PoolErrorLogger::class); - $this->bind()->annotatedWith('deadRedis')->toInstance(RedisAdapter::createConnection('redis://127.0.0.1:1')); + // lazy: ext-redis connects eagerly otherwise, and the boot-time throw is not + // the runtime outage this test simulates (Predis is lazy by default). + $this->bind()->annotatedWith('deadRedis')->toInstance(RedisAdapter::createConnection('redis://127.0.0.1:1?lazy=1')); $this->bind(TagAwareAdapterInterface::class)->annotatedWith(ResourceObjectPool::class)->toConstructor( RedisTagAwareAdapter::class, ['redis' => 'deadRedis'], @@ -80,7 +82,7 @@ public function testTheBackendsOwnMessageIsCarried(): void $context = (string) self::eventContextJsonOf($this->flushAndValidate($this->logger), 'pool_error'); $this->assertTrue(str_contains($context, 'Connection refused'), $context); - $this->assertStringContainsString('ConnectionException', $context, 'the throwable the adapter caught'); + $this->assertStringNotContainsString('"exceptionClass":"unknown"', $context, 'the throwable the adapter caught'); } public function testAMissIsStillRecordedSoTheReadPathIsNotSilent(): void From de1224648281703cd2195af105c4d5ce0a29a00e Mon Sep 17 00:00:00 2001 From: Akihito Koriyama Date: Wed, 19 Aug 2026 17:56:24 +0900 Subject: [PATCH 4/5] Wire the pool_error logger into the dedicated ETag pool A standalone StorageMemcachedEtagModule install bound its MemcachedAdapter without the PSR-3 logger, so a dead ETag store failed silently on the validator side - the silent-failure class this PR exists to kill. --- src/StorageMemcachedEtagModule.php | 18 ++++++++++++++---- 1 file changed, 14 insertions(+), 4 deletions(-) diff --git a/src/StorageMemcachedEtagModule.php b/src/StorageMemcachedEtagModule.php index 63c12210..13cdedfc 100644 --- a/src/StorageMemcachedEtagModule.php +++ b/src/StorageMemcachedEtagModule.php @@ -4,11 +4,14 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\PoolErrorLogger; use BEAR\RepositoryModule\Annotation\EtagPool; use Memcached; use Override; use Psr\Cache\CacheItemPoolInterface; +use Psr\Log\LoggerInterface; use Ray\Di\AbstractModule; +use Ray\Di\InjectionPoints; use Ray\PsrCacheModule\Annotation\CacheNamespace; use Ray\PsrCacheModule\Annotation\MemcacheConfig; use Ray\PsrCacheModule\MemcachedAdapter; @@ -40,10 +43,17 @@ public function __construct( #[Override] protected function configure(): void { - $this->bind(CacheItemPoolInterface::class)->annotatedWith(EtagPool::class)->toConstructor(MemcachedAdapter::class, [ - 'namespace' => CacheNamespace::class, - 'clientProvider' => 'memcached', - ]); + $this->bind(LoggerInterface::class)->annotatedWith('poolError')->to(PoolErrorLogger::class); + $this->bind(CacheItemPoolInterface::class)->annotatedWith(EtagPool::class)->toConstructor( + MemcachedAdapter::class, + [ + 'namespace' => CacheNamespace::class, + 'clientProvider' => 'memcached', + ], + // A dedicated ETag store that is down must reach the cache log too, + // or a failed validator read is an ordinary miss. + (new InjectionPoints())->addMethod('setLogger', 'poolError'), + ); $this->bind()->annotatedWith(MemcacheConfig::class)->toInstance($this->memcacheServer); $this->bind(MemcachedProvider::class); $this->bind(Memcached::class)->toProvider(MemcachedProvider::class); From 22a2c0bd98e4dd7b8c47079f8894f05d69976368 Mon Sep 17 00:00:00 2001 From: Akihito Koriyama Date: Wed, 19 Aug 2026 19:45:01 +0900 Subject: [PATCH 5/5] Make the backend-message assertion portable and cover the logger's filters Windows words a refused connection differently ('actively refused it'), so pinning the POSIX wording failed the windows jobs. The contract is that the backend's own message is carried: assert it is non-empty and the exception class is not 'unknown'. The same intent covers the two lines codecov flagged: a new test pins that non-failure levels are ignored and a failure with no operation word is recorded as operation 'unknown'. --- tests/PoolErrorLogTest.php | 23 ++++++++++++++++++++--- 1 file changed, 20 insertions(+), 3 deletions(-) diff --git a/tests/PoolErrorLogTest.php b/tests/PoolErrorLogTest.php index 14445317..f04bf7b8 100644 --- a/tests/PoolErrorLogTest.php +++ b/tests/PoolErrorLogTest.php @@ -4,10 +4,12 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\Context\GetContext; use BEAR\QueryRepository\Log\PoolErrorLogger; use BEAR\RepositoryModule\Annotation\CacheLog; use BEAR\RepositoryModule\Annotation\ResourceObjectPool; use BEAR\Resource\ResourceInterface; +use Koriym\SemanticLogger\SemanticLogger; use Koriym\SemanticLogger\SemanticLoggerInterface; use PHPUnit\Framework\TestCase; use Psr\Log\LoggerInterface; @@ -18,8 +20,6 @@ use Symfony\Component\Cache\Adapter\RedisTagAwareAdapter; use Symfony\Component\Cache\Adapter\TagAwareAdapterInterface; -use function str_contains; - /** * A store that cannot be reached, and what the log says about it * @@ -81,7 +81,9 @@ public function testTheBackendsOwnMessageIsCarried(): void $context = (string) self::eventContextJsonOf($this->flushAndValidate($this->logger), 'pool_error'); - $this->assertTrue(str_contains($context, 'Connection refused'), $context); + // The wording is the backend's own and differs by OS and client ("Connection refused" + // on POSIX, "actively refused" on Windows): what the log owes is a non-empty message. + $this->assertStringNotContainsString('"error":""', $context); $this->assertStringNotContainsString('"exceptionClass":"unknown"', $context, 'the throwable the adapter caught'); } @@ -96,4 +98,19 @@ public function testAMissIsStillRecordedSoTheReadPathIsNotSilent(): void $this->assertContains('cache_miss', $types); $this->assertContains('pool_error', $types); } + + public function testOnlyFailuresAreRecordedAndUnrecognizedWordingIsUnknown(): void + { + $logger = new SemanticLogger(); + $poolLogger = new PoolErrorLogger($logger); + $openId = $logger->open(new GetContext('app://self/value')); + $poolLogger->info('everything is fine'); // not a failure level: must not be recorded + $poolLogger->error('something happened'); // a failure with no operation word in it + $logger->close(new GetContext('app://self/value'), $openId); + + $tree = $this->flushAndValidate($logger); + + $this->assertSame(['get', 'pool_error', 'get'], self::collectTypes($tree)); + $this->assertStringContainsString('"operation":"unknown"', (string) self::eventContextJsonOf($tree, 'pool_error')); + } }