diff --git a/CHANGELOG.md b/CHANGELOG.md index 88acd1a4..cee9b47f 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 82156276..4da2c3fe 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,34 @@ 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'), + ); + // 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); +$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 0a33aa17..c779df0a 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`, … | ロガー自体の誤用(コア側の診断で、このパッケージの語彙ではない) | ## 結果が入るフィールド @@ -156,12 +157,30 @@ get page://self/html/blog-posting ← スコープ: open されて clos 内側から見た「stale を配信している」状態です。 **エントリが期限切れになる設計かどうかは、TTL ではなく `cache_policy.expiry` を読みます。** +`expiry: "never"` は「無効化が届くまで」という意図です。解決した数値は保険であり、アプリが `Expiry` を +どう束縛したかで変わります — 既定のインストールでは `never` が 31536000 秒になり、意図的な 1 年 TTL と +まったく同じに見えます。`expirySecond` か `expiryAt` が non-null 側なら、そのエントリは期限切れになり、 +どの宣言が決めたかも分かります。 + **`requestedTtl` は要求した値で、ストアがどうしたかではありません。** `0`/`null` は「このパッケージは 期限を設定しなかった」— つまり無効化が届くまで生きるはず、という意図です。それが可能かはバックエンドが 決めます。`symfony/cache` の `RedisTagAwareAdapter` は期限なしのタグ付きエントリに 8640000 秒(100 日)を 与えます — Redis はタグ集合を期限切れにできないからです。実効寿命はデプロイ側の事実なので、ストアで 読んでください(Redis なら `TTL `)。 +**コマンド注釈が届くのは 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` には何も届きません。アダプタは代わりに +失敗を PSR-3 ロガーへ報告し、プールにはキャッシュログが渡されています — だからストアが落ちているとき、 +miss の隣に `pool_error` が並びます(沈黙にはなりません)。そこで分かるのはプールのキーだけで、 +リソース URI ではありません。 + **`cdn_headers` に出るのは、応答に実際に付いたヘッダです。** CDN モジュールの暗黙の既定値も含みます。 lifetime ヘッダの無いマップは、CDN に lifetime 指示を与えなかった応答です。`surrogateKeys` と `invalidate` の `tags` を突き合わせると、パージがエッジの保持物に届き得たかが分かります。 diff --git a/docs/reading-the-log.md b/docs/reading-the-log.md index ef73c164..43a22ca0 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 @@ -159,12 +160,31 @@ correlation. Any `invalidate` without the marker is a real invalidation. which is what serving stale looks like from the inside. **Read `cache_policy.expiry`, not a TTL, to learn whether an entry is meant to expire.** +`expiry: "never"` means until invalidation; the number it resolves to is a backstop and depends on +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. + **`requestedTtl` is what was asked for, not what the store did.** `0`/`null` means this package set no expiry, so the entry is meant to live until an invalidation reaches it — but the backend decides whether that is possible. `symfony/cache`'s `RedisTagAwareAdapter` gives an unexpiring tagged entry 8640000 seconds (100 days), because Redis cannot expire tag sets. The effective lifetime is a property of the deployment, and the store is where to read it: `TTL ` on Redis. +**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 +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. Correlate its `surrogateKeys` with an `invalidate`'s `tags` to see whether a purge could reach 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 e3e5b5b9..36af6b41 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 5a92d87c..0d5cea19 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( + is_string($key) ? $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/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); 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..f04bf7b8 --- /dev/null +++ b/tests/PoolErrorLogTest.php @@ -0,0 +1,116 @@ +bind(LoggerInterface::class)->annotatedWith('poolError')->to(PoolErrorLogger::class); + // 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'], + (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'); + + // 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'); + } + + 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); + } + + 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')); + } +}