diff --git a/CHANGELOG.md b/CHANGELOG.md index 486e96af..88acd1a4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -38,6 +38,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - `LogSinkInterface`/`ShutdownFlush` and `LogWriterInterface`/`LogFileWriter`/`LogStreamWriter`: the log module owns flushing, so no app writes `flush()` in a bootstrap. The sink arms once per process - at construction and again at `SafeSemanticLogger::__unserialize()`, the only hook that runs on every request - and fires after output, after a 304's early `exit()` and after an uncaught error, which a hook on `ResourceObject::transfer()` cannot do (rendering happens inside it, and a 304 never reaches it). The flush is total: a destination that throws is reported to `error_log()` and swallowed, because from a shutdown callback it would otherwise surface as an uncaught fatal after the response was already written. An empty session is never written; `LogFileWriter` creates 0700/0600, names sessions in UTC with a microsecond field so pruning keeps the newest, renames `latest.json` into place so a reader never opens a half-written file, and reports a destination it cannot write instead of emitting warnings from a shutdown handler. - 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). - `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/docs/reading-the-log.ja.md b/docs/reading-the-log.ja.md index e60ded90..0a33aa17 100644 --- a/docs/reading-the-log.ja.md +++ b/docs/reading-the-log.ja.md @@ -86,6 +86,7 @@ get page://self/html/blog-posting ← スコープ: open されて clos | 型 | フィールド | 何が分かるか | |---|---|---| +| `cache_policy` | `uri`, `expiry`, `expirySecond`, `expiryAt`, `resolvedTtl` | リソースが宣言した寿命と、それが解決した値 | | `save_value` | `uri`, `tags`, `requestedTtl`, `saved` | body をプールに渡した | | `save_view` | `uri`, `tags`, `requestedTtl`, `saved` | body + レンダリング済み view を渡した | | `save_etag` | `uri`, `etag`, `tags`, `requestedTtl`, `saved` | 検証子を ETag プールに渡した | @@ -154,6 +155,7 @@ get page://self/html/blog-posting ← スコープ: open されて clos 突き合わせます。交差しないタグは、その書き込みがそのエントリを残したことを意味します — これが 内側から見た「stale を配信している」状態です。 +**エントリが期限切れになる設計かどうかは、TTL ではなく `cache_policy.expiry` を読みます。** **`requestedTtl` は要求した値で、ストアがどうしたかではありません。** `0`/`null` は「このパッケージは 期限を設定しなかった」— つまり無効化が届くまで生きるはず、という意図です。それが可能かはバックエンドが 決めます。`symfony/cache` の `RedisTagAwareAdapter` は期限なしのタグ付きエントリに 8640000 秒(100 日)を diff --git a/docs/reading-the-log.md b/docs/reading-the-log.md index aef1d360..ef73c164 100644 --- a/docs/reading-the-log.md +++ b/docs/reading-the-log.md @@ -88,6 +88,7 @@ operation inside a GET or a command is an ordinary event there instead. | Type | Fields | What it tells you | |---|---|---| +| `cache_policy` | `uri`, `expiry`, `expirySecond`, `expiryAt`, `resolvedTtl` | what the resource declared about its lifetime, and what that resolved to | | `save_value` | `uri`, `tags`, `requestedTtl`, `saved` | the body was offered to the pool | | `save_view` | `uri`, `tags`, `requestedTtl`, `saved` | body + rendered view were offered | | `save_etag` | `uri`, `etag`, `tags`, `requestedTtl`, `saved` | the validator was offered to the ETag pool | @@ -157,6 +158,7 @@ correlation. Any `invalidate` without the marker is a real invalidation. `tags` of a later `invalidate`. Tags that do not meet mean the write left that entry standing — 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.** **`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 diff --git a/docs/schemas/context/cache_policy.json b/docs/schemas/context/cache_policy.json new file mode 100644 index 00000000..00e0fc54 --- /dev/null +++ b/docs/schemas/context/cache_policy.json @@ -0,0 +1,46 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/cache_policy.json", + "title": "cache_policy", + "description": "Event: what the resource declared about its lifetime. `expiry: \"never\"` means the entry is meant to live until an invalidation reaches it; every other declaration means it expires. Read this rather than `resolvedTtl` to learn the intent: the `never` preset resolves to a finite number whose value depends on how the application bound `Expiry`.", + "type": "object", + "required": [ + "uri", + "expiry", + "expirySecond", + "expiryAt", + "resolvedTtl" + ], + "properties": { + "uri": { + "type": "string" + }, + "expiry": { + "description": "the `#[Cacheable]` preset that decided this entry (`short` | `medium` | `long` | `never`), or null when a more specific declaration did", + "type": [ + "string", + "null" + ] + }, + "expirySecond": { + "description": "the declared lifetime in seconds, or null when it did not decide this entry", + "type": [ + "integer", + "null" + ] + }, + "expiryAt": { + "description": "the body field carrying an expiry timestamp, or null when it did not decide this entry", + "type": [ + "string", + "null" + ] + }, + "resolvedTtl": { + "description": "seconds the declaration resolved to - what the pools are asked for in the save events that follow", + "type": "integer", + "minimum": 0 + } + }, + "additionalProperties": false +} diff --git a/docs/what-the-log-proves.ja.md b/docs/what-the-log-proves.ja.md index c3e58f1e..e3e5b5b9 100644 --- a/docs/what-the-log-proves.ja.md +++ b/docs/what-the-log-proves.ja.md @@ -14,6 +14,7 @@ | 4 | 条件付きリクエストはエッジで再検証されたか？ | layer `etag` で `cache_hit`/`cache_miss` を閉じる `conditional_request` `{ifNoneMatch}` — リソースが 1 つも走る前に下される 304 の判定 | `HttpCacheInterface` の両実装が記録する。どちらかの記録を落とすか結果を入れ替えるとスイートが失敗する | | 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 が同じ寿命として記録される | ## 強制の層 diff --git a/docs/what-the-log-proves.md b/docs/what-the-log-proves.md index 38b9b9de..5a92d87c 100644 --- a/docs/what-the-log-proves.md +++ b/docs/what-the-log-proves.md @@ -21,6 +21,7 @@ is removed or its meaning inverted (verified by mutation testing). | 4 | Did a conditional request revalidate at the edge? | `conditional_request` `{ifNoneMatch}` closing `cache_hit`/`cache_miss` at layer `etag` — the 304 decision, made before any resource runs | Both `HttpCacheInterface` implementations record it; dropping either recording or swapping the outcome fails the suite | | 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 | ## The enforcement layers diff --git a/src/Log/Context/CachePolicyContext.php b/src/Log/Context/CachePolicyContext.php new file mode 100644 index 00000000..27614281 --- /dev/null +++ b/src/Log/Context/CachePolicyContext.php @@ -0,0 +1,34 @@ +getExpiryTime($ro, $cacheable); + if ($cacheable instanceof Cacheable) { + $this->logger->event($this->cachePolicy($ro, $cacheable, $ttl)); + } + ($this->headerSetter)($ro, $ttl, $httpCache); if (isset($ro->headers[Header::ETAG])) { $etag = $ro->headers[Header::ETAG]; @@ -99,6 +104,27 @@ private function doPut(ResourceObject $ro): bool return $this->storage->saveValue($ro, $ttl); } + /** + * The declaration that decided the lifetime, as declared. + * + * The precedence is the one {@see self::getExpiryTime()} applies: an expiry field in the body + * wins, then an explicit second count, then the preset. Only the winner is recorded, so a + * reader never has to re-derive which of the three was in force. + */ + private function cachePolicy(ResourceObject $ro, Cacheable $cacheable, int $ttl): CachePolicyContext + { + $uri = (string) $ro->uri; + if ($cacheable->expiryAt !== '') { + return new CachePolicyContext($uri, null, null, $cacheable->expiryAt, $ttl); + } + + if ($cacheable->expirySecond !== 0) { + return new CachePolicyContext($uri, null, $cacheable->expirySecond, null, $ttl); + } + + return new CachePolicyContext($uri, $cacheable->expiry, null, null, $ttl); + } + private function setCacheDependency(ResourceObject $ro): void { /** @var mixed $body */ diff --git a/tests/CachePolicyLogTest.php b/tests/CachePolicyLogTest.php new file mode 100644 index 00000000..f42d85ac --- /dev/null +++ b/tests/CachePolicyLogTest.php @@ -0,0 +1,82 @@ +resource = $injector->getInstance(ResourceInterface::class); + $this->logger = $injector->getInstance(SemanticLoggerInterface::class, CacheLog::class); + + parent::setUp(); + } + + public function testAPresetIsRecordedAsDeclaredBesideTheNumberItResolvedTo(): void + { + $this->resource->get('app://self/entry', ['id' => 1]); // #[Cacheable(expiry: 'never')] + + $policy = self::eventContextJsonOf($this->flushAndValidate($this->logger), 'cache_policy'); + + $this->assertNotNull($policy); + $this->assertStringContainsString('"expiry":"never"', $policy, 'the word the resource declared'); + $this->assertStringContainsString('"expirySecond":null', $policy, 'seconds did not decide this entry'); + $this->assertStringContainsString('"expiryAt":null', $policy); + // The number is a backstop, and a default install turns `never` into 365 days - which is + // why the word has to be in the log: this reads exactly like a deliberate 1-year TTL. + $this->assertStringContainsString('"resolvedTtl":31536000', $policy); + } + + public function testAnExplicitSecondCountIsTheDeclarationThatDecided(): void + { + $this->resource->get('app://self/control-none'); // #[Cacheable(expirySecond: 60)] + + $policy = self::eventContextJsonOf($this->flushAndValidate($this->logger), 'cache_policy'); + + $this->assertNotNull($policy); + $this->assertStringContainsString('"expirySecond":60', $policy); + $this->assertStringContainsString('"expiry":null', $policy, 'the preset is not what decided'); + $this->assertStringContainsString('"resolvedTtl":60', $policy); + } + + public function testAnExpiryFieldInTheBodyOutranksThePreset(): void + { + $this->resource->get('app://self/control-expiry'); // #[Cacheable(expiryAt: 'expiry_at')] + + $policy = self::eventContextJsonOf($this->flushAndValidate($this->logger), 'cache_policy'); + + $this->assertNotNull($policy); + $this->assertStringContainsString('"expiryAt":"expiry_at"', $policy, 'the body field that carries the deadline'); + $this->assertStringContainsString('"expiry":null', $policy); + $this->assertStringContainsString('"expirySecond":null', $policy); + } + + public function testAResourceWithNoCacheableDeclarationHasNoPolicy(): void + { + // The log carries a policy only where a declaration exists to record. + $this->resource->get('app://self/no-http-cache-control'); + + $this->assertNull(self::eventContextJsonOf($this->flushAndValidate($this->logger), 'cache_policy')); + } +}