diff --git a/CHANGELOG.md b/CHANGELOG.md index c7af04a8..ced79548 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -54,6 +54,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Removed - `docs/schemas/repository-log.json` (the flat op-string log format it described is gone; per-context schemas in `docs/schemas/context/` replace it). - `BEAR\QueryRepository\Log\NullSemanticLogger`: koriym/semantic-logger 0.9 ships its own no-op logger whose `open()` returns a usable id instead of the empty-string sentinel this one returned. +- `skills/bear-cache-log/`: folded into [bear-observe](https://github.com/bearsunday/BEAR.EventSourcing/blob/1.x/skills/bear-observe/SKILL.md), which sets the observation context up and proves it instead of teaching the wiring by hand. ### Changed - Cache logging call sites (`QueryRepository`, `ResourceStorage`, `DonutRepository`, `CacheInterceptor`, `AbstractDonutCacheInterceptor`, `CommandInterceptor`, `RefreshInterceptor`) now emit typed contexts through `SemanticLoggerInterface` annotated with `#[CacheLog]` instead of `RepositoryLoggerInterface::log()`. diff --git a/README.ja.md b/README.ja.md index 068b3254..017417ba 100644 --- a/README.ja.md +++ b/README.ja.md @@ -25,4 +25,4 @@ - [ログの読み方](docs/reading-the-log.ja.md) — ログに現れる全ての語と、セッションの読み方 - [QueryRepository ログはなぜ全てを記録するのか](docs/why-the-log-records-everything.ja.md) — 設計根拠、コスト実測、既定オフの判断 - [このログは何を証明し、何を証明しないか](docs/what-the-log-proves.ja.md) — ログが答える問い、その答えを正直に保つ機構、そして宣言された境界 -- [エージェント用スキル: キャッシュログを読む](skills/bear-cache-log/SKILL.md) — `vendor/bear/query-repository/skills/` からプロジェクトの `.claude/skills/` にコピーして、コーディングエージェントに推測ではなくログを観測させる。配線、イベント語彙、宣言と実際の照合、アプリとライブラリの切り分け、報告の形 +- エージェント用スキル: [bear-observe](https://github.com/bearsunday/BEAR.EventSourcing/blob/1.x/skills/bear-observe/SKILL.md) — 観測文脈を設置し、1 リクエストを木にして読む。イベント語彙、宣言と実際の照合、アプリとライブラリの切り分け、報告の形 diff --git a/README.md b/README.md index c39413d5..50ca4268 100644 --- a/README.md +++ b/README.md @@ -25,4 +25,4 @@ - [Why the QueryRepository Log Records Everything](docs/why-the-log-records-everything.md) — design rationale, the cost measurements, and why recording is off by default - [Reading the Log](docs/reading-the-log.md) — every word the log can contain, and how to read a session - [What the Cache Log Proves — and What It Does Not](docs/what-the-log-proves.md) — the questions the log answers, the mechanisms that keep the answers honest, and the declared boundaries -- [Agent skill: reading the cache log](skills/bear-cache-log/SKILL.md) — copy it out of `vendor/bear/query-repository/skills/` into your project's `.claude/skills/` so a coding agent observes the log instead of guessing: wiring, the event vocabulary, how a declaration is checked against what the log shows, app-vs-library triage, and what to report. Written in Japanese +- Agent skill: [bear-observe](https://github.com/bearsunday/BEAR.EventSourcing/blob/1.x/skills/bear-observe/SKILL.md) — sets up an observation context, renders one request as a tree, and reads it: the event vocabulary, how a declaration is checked against what the log shows, app-vs-library triage, and what to report. Written in Japanese diff --git a/skills/bear-cache-log/SKILL.md b/skills/bear-cache-log/SKILL.md deleted file mode 100644 index 2f109810..00000000 --- a/skills/bear-cache-log/SKILL.md +++ /dev/null @@ -1,383 +0,0 @@ ---- -user-invocable: true -name: bear-cache-log -description: BEAR.Sunday のキャッシュ挙動をセマンティックログで観測し、宣言した意図どおりに動いているかを自分で確かめ、食い違えばアプリかライブラリかを切り分けて報告する。Use when user says "キャッシュログ", "cache log", "キャッシュが効いてるか確認", "purgeが効かない", "304が返らない", "キャッシュが古い", "アプリかライブラリか切り分けて", or asks to observe, verify, or debug BEAR.Sunday caching behaviour. ---- - -# セマンティックキャッシュログ — 観測し、意図と照合し、切り分ける - -キャッシュの誤りは沈黙する。**一度も効いていないリソースも、正しい答えを返し続ける**。 -テストは緑のままで、遅いだけ、あるいは古いだけになる。見るのはコードではなくログで、順番は決まっている。 - -```text -1. 導入 記録を on にして、配線が生きていることを実証する -2. 読む 運用の問い ↔ イベントの対応 -3. 照合 宣言した意図は、どのイベント列として現れるはずか -4. 切り分け 食い違ったら、アプリの問題かライブラリの問題か -5. 報告 根拠つきで、どちらかを言う -``` - -**前提**: `bear/query-repository` がセマンティックログを含む版であること -([PR #178](https://github.com/bearsunday/BEAR.QueryRepository/pull/178) 以降)。 -未リリースの間は `composer require bear/query-repository:"1.x-dev#"`。 - -このファイル自体の導入(コーディングエージェントに読ませる)。vendor から取ると、アプリが使っている版の -スキルが入る: - -```bash -mkdir -p .claude/skills && cp -r vendor/bear/query-repository/skills/bear-cache-log .claude/skills/ -``` - -まだ `composer require` していない、あるいは GitHub で読んでいるなら: - -```bash -mkdir -p ~/.claude/skills/bear-cache-log && curl -fsSL \ - https://raw.githubusercontent.com/bearsunday/BEAR.QueryRepository/1.x/skills/bear-cache-log/SKILL.md \ - -o ~/.claude/skills/bear-cache-log/SKILL.md -``` - -## 正典ドキュメント(推測で補完しない) - -`docs/` と `demo/` は `.gitattributes` で `export-ignore` — 通常の `composer require` の vendor には**入らない**。 -GitHub で読むか `composer reinstall bear/query-repository --prefer-source` で取る。 - -| 知りたいこと | どこ | -|---|---| -| **語彙全部と読み方(まずこれ)** | [docs/reading-the-log.md](https://github.com/bearsunday/BEAR.QueryRepository/blob/1.x/docs/reading-the-log.md) | -| ログが答える問いと保証の境界 | [docs/what-the-log-proves.md](https://github.com/bearsunday/BEAR.QueryRepository/blob/1.x/docs/what-the-log-proves.md) | -| 設計根拠・コスト実測・既定オフの理由 | [docs/why-the-log-records-everything.md](https://github.com/bearsunday/BEAR.QueryRepository/blob/1.x/docs/why-the-log-records-everything.md) | -| 各 context のスキーマ(28 種) | [docs/schemas/context/](https://github.com/bearsunday/BEAR.QueryRepository/tree/1.x/docs/schemas/context) — 各イベントの `schemaUrl` が正典 | -| 動く実例(自己検証つき) | [demo/](https://github.com/bearsunday/BEAR.QueryRepository/tree/1.x/demo) | - -## 1. 導入(記録は既定でオフ) - -`QueryRepositoryModule` は `SemanticLoggerInterface` に `NullSemanticLogger` を束縛する。 -**何も記録されず、蓄積もせず、flush 責務も発生しない。** 記録するにはモジュールを install する: - -```php -// 開発 — 1 リクエスト = 1 ファイル + latest.json -$this->install(new DevQueryRepositoryLogModule($appDir . '/var/log/query-repository', module: new QueryRepositoryModule())); - -// 本番 — セッションを積んで flush 時に判定(mutation / 失敗 / サンプルだけ残す) -// 出力先に何が流れるかは、下の最終項(セッションが含む値)を先に読む -$this->install(new ProdQueryRepositoryLogModule('php://stdout', sampleRate: 1000, module: new QueryRepositoryModule())); -``` - -- **`module:` で包むのが必須**。`install()` は既存束縛を上書きしない(Ray.Di の `Container::merge()` は `+=`)。 - `QueryRepositoryModule` を別に install すると **null のまま無音**になる -- **包んだモジュールは「足す」のではなく「置き換える」**。アプリが既に `QueryRepositoryModule` を持つ - (BEAR.Package 経由など)のに、上から `module: new QueryRepositoryModule()` を足すと **Ray.Aop の - pointcut が累積してインターセプタが 2 回走る** — 1 リクエストで参照 2 回・書き込み 2 回、ログには - 同じ URI が自分の中に入れ子で現れる。既存グラフに記録だけ足すなら、包まずに - `bind(SemanticLoggerInterface::class)->annotatedWith(CacheLog::class)` の 1 本だけを差し替える -- **flush はモジュールの仕事**。`LogSinkInterface`(`ShutdownFlush`)がプロセスごとに 1 回仕込む。 - アプリに書く flush は **0 行**。304 の早期 `exit()` でも未捕捉例外でも記録は残る -- 書き込み先が壊れていても例外にはならない。`error_log()` に報告して黙る(ログは side channel) -- **並行ランタイム**: RoadRunner(`RR_MODE`)や Swoole コルーチン内では sink が arm を拒否し、**記録ごと - 止まる**(理由は `error_log`)。ワーカー常駐の CLI 消費者は検出できないので install しない -- セッションは URI(クエリ文字列込み)・client validator・生の例外文を含む。`LogFileWriter` は 0700/0600 - で作る。scrub や流量制限は `LogWriterInterface` を decorate する - -ツリー表示: `vendor/bin/stree var/log/query-repository/latest.json`(ファイル引数。オプションは `--help`)。 - -**hit と miss は `stree` では読めない。** hit/miss はスコープの**閉じ方**(close の型)で、`stree` は close 行に -context のフィールドしか出さない — 2 つの `get` は `durationMs` でしか違わず、それは判定に使ってはいけない値だ -(§2)。判定は JSON を直接見る: - -```bash -jq -r '[.. | objects | select(.type? == "get")] | .[] | - "\(.context.uri) -> \(.close.type)"' var/log/query-repository/latest.json -# app://self/user?id=1 -> cache_miss -# app://self/user?id=1 -> cache_hit -``` - -**空の結果そのものが一次診断になる。** ただしこれが言うのは「この JSON に `get` スコープが無い」までだ。 -`#[Cacheable]` なリソースを実際に GET したセッションを見ている、と確かめてはじめて、1 行も返らないことが -インターセプタが織られていない証拠になる(§2)。「ログが読めない」ではなく「宣言が届いていない」と読む。 -見ているセッションが違うなら次項。 - -**ファイルが無い現場もある。** テストやオラクルは `DevQueryRepositoryLogModule` を使わず、 -`SemanticLoggerInterface` `#[CacheLog]` に `SafeSemanticLogger`(sink 無し)を束縛して、自分で -`flush()` を受け取るのが普通だ。この形では `var/log/query-repository` は一度も作られない。 -観測する側が sink になるので、読み方はファイルではなく戻り値: - -```php -$logger = $injector->getInstance(SemanticLoggerInterface::class, CacheLog::class); -$resource->get($uri); // 操作 -$log = $logger->flush(); // その場で受け取る(以降は次のセッション) -``` - -`flush()` は 1 回で使い切る。操作ごとに呼べばステップ単位で見られるが、**呼んだ後に前のイベントは -残らない**。`latest.json` を探して「ログが無い」と結論する前に、対象のテストやスクリプトが自分で -束縛していないかを読む。 - -### 他のパッケージのログと 1 本の木にする - -BEAR.EventSourcing の `resource_request` の内側にキャッシュのスコープを入れたい、のような場合は -**同じ logger を 2 つの束縛キー(素のキーと `#[CacheLog]`)が指す**必要がある。Ray.Di の Scope は -束縛キー単位で、`to()` は対象クラスのスコープを継がない — 具象を Singleton にしても、`to()` した -インターフェイスキーは毎回別のインスタンスになる。だから `to()` も `toConstructor()` ではこれはできない。 -provider で素のキーの Singleton をそのまま返す: - -```php -$this->bind(SemanticLoggerInterface::class)->annotatedWith(CacheLog::class) - ->toProvider(SharedCacheLogProvider::class)->in(Scope::SINGLETON); -``` - -**サービスを `toInstance` で渡さない。** DI が構築を握らなくなるうえ、束縛にオブジェクトが載るので -closure を持つものを渡すと `serialize($injector)` が落ちる(コンパイル済み injector を使い回す構成で止まる)。 -点検は型ではなく同一性で: - -```php -$injector->getInstance(SemanticLoggerInterface::class) - === $injector->getInstance(SemanticLoggerInterface::class, CacheLog::class); -``` - -**これが `false` だと、キャッシュのイベントだけが静かに消える**(実測: `to()` で束縛したら -`resource_request` は出続け、`get`/`save_value`/`cache_hit` が 1 件も出なくなった。例外は出ない)。 -観測系のモジュールは対象より**先に** install する — 後にすると、そのログだけが無音で消える。 - -依存の伝播はこの 2 本を突き合わせる。`depends_on` の子タグが `save_*` の `tags` に現れていなければ、 -そこで途切れている: - -```bash -jq -r '[.. | objects | select(.type? | test("^(depends_on|save_value|save_etag|invalidate)$"))] | .[] | - "\(.type)\t\(.context.uri // "")\t\((.context.tags // .context.childTags // []) | join(","))"' log.json -# depends_on page://self/dep/parent-a _dep_child-c_ -# save_value page://self/dep/parent-a _dep_parent-a_,_dep_child-c_ <- 子タグが乗っている -``` - -**読むのは今回の実行が書いたものか。** `latest.json` はリクエストごとに入れ替わる。リポジトリに commit -されたサンプル出力(このライブラリなら `demo/logs/*.log`)を判定に使うと、**自分の変更が反映されない結果を -測ることになる**。実行直後の mtime を見る、または実行の stdout をそのまま読む。 - -スキーマ検証: `vendor/bin/validate-semantic-log.php ` -(`--prefer-source` なら `vendor/bear/query-repository/docs/schemas/context`。dist ならスキーマを -アプリ側にコピーしてリポジトリ管理する — スキーマは公開契約なので固定して持つことに意味がある)。 - -### 配線を点検する - -記録が既定でオフなので、**「ログが無い」と「モジュールが入っていない」は出力から区別できない**。 -間違った入れ方も無音。だから点検は束縛から解き、最後に 1 リクエストで実証する。 -文脈(dev / prod / test / CLI)ごとに injector を作り、ファイル名から推測せずに取る: - -```php -$injector->getInstance(SemanticLoggerInterface::class, CacheLog::class); // Null なら記録なし -$injector->getInstance(LogWriterInterface::class); // 実効の書き先 -$injector->getInstance(LogSinkInterface::class); // flush 境界 -``` - -| 点検 | 捕まえる失敗 | -|---|---| -| `#[CacheLog]` の logger が `SafeSemanticLogger` か | `NullSemanticLogger` のまま = `module:` で包んでいない、または別 install で無音 | -| dev は `LogFileWriter`、prod は `LogStreamWriter`(または `PsrLogWriter`) | 本番に dev 形: 全セッション書き出し・保持方針なし | -| `LogFileWriter` のディレクトリが**専用**か | `keep` を超えると `YYYYMMDD-HHMMSS-*.json` 形の古いファイルを消す。アプリの `var/log` を共有すると同形の無関係ファイルが消える | -| `LogStreamWriter` の先が `php://stdout`/`stderr`/`output` か、プロセスが書けるパスか | wrapper 文字列は構築時に拒否されるが、書けないパスは実行時に `error_log` に出るだけ | -| ホストが 1 プロセス 1 リクエストか | RoadRunner / Swoole コルーチンは sink が拒否。FrankenPHP worker・ReactPHP・Amp・常駐 CLI は**検出されない** — 分類できないホストには勧めず、聞く | -| `SemanticLoggerInterface` が他所で `Scope::SINGLETON` 無しに束縛されていないか | 2 つ目の logger が同じ sink を arm すると flush されない(`error_log` に "a second logger armed an already-armed sink") | -| injector をシリアライズする文脈(compiled app)に `PsrLogWriter` が無いか | closure を持つ Monolog を抱え、コンパイル済みグラフが unserialize できなくなる | - -**実証**: 配線の主張で終わらせない。1 リクエスト流して到達を見る。 - -```bash -php public/index.php get / # dev: latest.json が更新され get スコープが入る -vendor/bin/stree var/log/query-repository/latest.json -``` - -到達しなければ `error_log`(FPM なら SAPI のエラーログ)を見る。sink の拒否・二重 arm・書けない先は全部そこ。 - -## 2. 観測の前提(ここを外すと、測っているものが別物になる) - -- **プールは既定で `NullAdapter`**。文脈が何も束縛していなければ 1 件も保存されない。テストで観測するなら - override module で `AdapterInterface` を `#[ResourceObjectPool]` 付きで `ArrayAdapter` に束縛する(Redis 不要) -- **ETag プールも既定で未束縛**(`TagAwareAdapterInterface` `#[EtagPool]` → `toInstance(null)`)。 - 束縛されていなければ `save_etag` は一度も出ず、**304 も返らない**。「304 が返らない」の最初の点検はここ -- **qualifier は `BEAR\RepositoryModule\Annotation\*`**(`CacheLog`, `ResourceObjectPool`, `TagsPool`, `EtagPool`)。 - `BEAR\QueryRepository\Annotation\` にも同名クラスがあり、**間違えても例外は出ない** — 自分の - `getInstance()` が同じ間違った key で答えるので「束縛は効いている」ように見える。プールの中身を数えて確かめる - (`ArrayAdapter::getValues()`) -- **override には module を install しない**、`bind` だけにする。storage module を入れると - `QueryRepositoryModule` が二重になり pointcut が積まれる -- **`final class` はインターセプタを受け取れない**。Ray.Aop はクラスを継承して織るので、`final` なリソースの - `#[Cacheable]` は静かに無効になり、**ログは miss すら出さず空**になる。検査: - - ```php - get_class($injector->getInstance($class)) !== $class; // false なら織られていない - $injector->getInstance($class)->bindings; // メソッド名 => 付いたインターセプタ - ``` - -- **weave が変わったら `composer clean`**(コンパイル済み DI が残っていると直した後も織られない) -- **時間差で判定しない**。プロセス内では refill も 1ms 台で hit と区別できない。判定は必ずイベントで行う -- **プリセットの実数**は `Expiry`: `short` 60 / `medium` 3600 / `long` 86400 / `never` 31536000 秒。 - アプリが `StorageExpiryModule` で上書きするので、数値を書き写さず injector から `Expiry` を取って - `getTime()` で解決する - -## 3. 読む — 運用の問い ↔ イベント - -| 問い | 見るイベント | -|---|---| -| **キャッシュは効いたか** | `get` スコープの **close の型**(`cache_hit` / `cache_miss`)。`stree` は出さないので上の `jq` で見る | -| このレスポンスは保存されたか、何秒、どのキーで | `save_value` / `save_view` / `save_etag` / `save_donut` / `save_donut_view` の `{tags, ttl, saved}` | -| CDN に何を何秒キャッシュさせたか | `cdn_headers` の `headers`(応答の literal ヘッダ。**setter の既定値もここに出る**)。lifetime ヘッダが無い = CDN はキャッシュしない | -| purge は何を対象にし、効いたか | `invalidate` の `{tags, roPool, etagPool, cdn}`。`cdn` は `purged`/`failed`/`skipped` の三値、fail-closed | -| エッジの再検証(304)はヒットしたか | `conditional_request` スコープが `cache_hit{layer: etag}` で閉じる = リソースを走らせず 304 | -| なぜ保存されていないのか | `put_skipped` の `{reason, code}`(`etag-present` / `error-code` / `not-cacheable`) | -| miss は空だったのか、店が読めなかったのか | 同じスコープに `cache_error{operation: read}` があれば縮退。無ければコールド。**本番では読み取りだけのセッションは残らない**ので、この切り分けは開発時のもの | -| 誰が書いた/消したか | `command` スコープの `source`。直接呼び出しは `manual_store`/`manual_purge`/`manual_invalidate`。`pre_write_cleanup` 直後の `invalidate` は**書き込み前掃除であり実無効化ではない** | -| 依存の伝播 | `depends_on` と、`save_*` の `tags` ↔ `invalidate` の `tags` の突き合わせ | -| hit/miss はどの層か | close の `layer`: `resource`(値キャッシュ) / `donut` / `donut-view` / `etag`(304 判定)の 4 値 | -| `put_skipped` が出ている | **close が `cache_hit` のスコープの `put_skipped` は正常**(既に保存済みのものを再保存しない)。欠陥として読むのは `cache_miss` で閉じたスコープに出たときだけ | - -## 4. 意図と実際を照合する - -宣言は意図の表明でしかない。**効いている証拠はイベント列**。下表は `1.x`(`5abe573`)で `demo/run*.php` と -`tests/Fake/fake-app/src/Resource/Page/Mx` の fixture を実行して得た列 = **その版で期待される形**。 -手元の出力がこれと違えば、それが所見であって表の誤りではない。 - -| 宣言 | コールド read | 2 回目 | 自分への書き込み | -|---|---|---|---| -| `#[Cacheable]` | close `cache_miss`。`cache_policy{expiry, resolvedTtl}` → `save_etag` → `save_value` | close `cache_hit`、イベント 0 件 | `command{source: CommandInterceptor}` に `purge` → `invalidate`、続いて**入れ子の `get` で再生成**(`RefreshSameCommand`)。close は `command_result` | -| `#[CacheableResponse]` | close `cache_miss{layer: donut}`。`put_donut` → `cdn_headers` → **`save_etag`** → `save_donut_view` → `save_donut`(全体を保存し ETag を持つ = 304 が返る) | close `cache_hit`、イベント 0 件。埋め込んだ子が無効化された回だけ `refresh_donut` → `save_etag` → `save_donut_view` | `#[Purge]`/`#[Refresh]`/`#[RefreshCache]` のいずれでも `command_result [purge, invalidate]`、次の read は `cache_miss`。**1.16.2 以前は `#[RefreshCache]` だけ書き込みが実行されない**(下の注) | -| `#[DonutCache]` | close `cache_miss`。`put_donut` → `cdn_headers` → `save_donut`。**`save_etag` は出ない** — 全体を保存しないので ETag も無く、304 は返らない | close `cache_hit` + `refresh_donut` → `put_skipped{not-cacheable}`。毎回 donut を組み直すのが正常 | 書き込み側に `#[Purge]`/`#[Refresh]`/`#[RefreshCache]` を書かないと、`command` も `invalidate` も出ない | -| `#[Embed]` した子を持つ親 | `depends_on` が出て、`save_*` の `tags` に子の URI タグが入る | close `cache_hit` | 子を purge → 親の次の read が `cache_miss` | -| `#[Refresh]` / `#[Purge]` | — | — | `command` スコープに `purge` + `invalidate`。`pre_write_cleanup` 隣接**だけ**なら誰にも告げていない | -| `#[HttpCache]` | `cdn_headers` に literal ヘッダ | 同じ | — | - -**1.16.2 以前は、書き込みメソッドに `#[RefreshCache]` を付けるとキャッシュが温まっている間その書き込みが -実行されない。** `DonutCacheModule` が `#[RefreshCache]` に **query 用の `DonutCacheInterceptor`** を束縛し、 -それは `donutRepository->get()` が当たった時点で `proceed()` を呼ばずにキャッシュ済み表現を返す(HTTP -メソッドを見ていない)。実測: 先に GET してから DELETE すると `onDelete` の本体は **0 回**、応答は宣言した -204 ではなく **200 + キャッシュ済みの表現**。GET せずに DELETE すれば 1 回走る。 - -[#215](https://github.com/bearsunday/BEAR.QueryRepository/pull/215) で修正済み(次のリリースに入る)。 -古い版を使っているなら書き込みは `#[Purge]` / `#[Refresh]` で宣言する。なお `#[Cacheable]` クラスでは -`#[RefreshCache]` は何も足さない — `CommandInterceptor` が既に purge して再生成する。 - -読み間違えやすい 3 点(いずれも実測): - -1. **コールドの `get` にも `pre_write_cleanup` → `invalidate` が出る。** 保存の前に自分の古いエントリを - 消しているだけで、無効化ではない -2. **`cache_miss` は close の型としてもイベントとしても現れる**(donut は内側の層でも出す)。 - 「miss のイベントがある」は「そのスコープが miss で閉じた」ではない -3. **`#[Cacheable]` は自分の書き込みでは落ちるが、他所の書き込みでは落ちない。** 他のリソースが自分の - タグを announce しない限り、TTL が唯一の eviction になる - -食い違いの読み方: **期待した `save_*` が無い**なら宣言が届いていない(§2 の 3 点を先に潰す)。 -**`invalidate` があるのに `cache_miss` にならない**ならタグが交わっていない(下記)。 - -### 依存が効いているかを確かめる手順 - -「親が子を埋め込んでいるから、子を purge すれば親も落ちる」は**コードを読んでも分からない**: - -1. 親をコールドで読む。`save_*` の `tags` に**子の URI タグが入っている**ことを見る(入っていなければ依存は - 記録されていない — `#[Embed]` ではなく値をコピーしている疑い) -2. 子の URI を purge する(`QueryRepositoryInterface::purge(new Uri(...))`) -3. 親をもう一度読む。**`cache_miss` で閉じれば依存は生きている**。`cache_hit` なら親は古い子を抱えている - -`depends_on` は 1 の裏付け、2→3 が実証。効果だけ(値が変わった)で判定すると、TTL で落ちただけの場合と -区別できない。 - -**入れ子の `get` スコープは依存の証拠にならない。** 親のスコープの中に子のスコープが現れるのは、 -親の実行中に子を読んだという事実だけを言う。`ResourceInterface` を注入して手で読んでも同じ形になり、 -`depends_on` もタグ伝播も起きない。見るのは入れ子ではなく `depends_on` と `tags`。 - -**`#[Embed]` を付けただけでは足りない。** 依存を登録するのは `QueryRepository::setCacheDependency()` で、 -保存時に **`$ro->body` に `AbstractRequest` のインスタンスが残っているものだけ**を辿る。埋め込んだ値を -スカラーに解決して body を作り直すと、その時点で Request は body から消えており、依存は登録されない。 -body に Request(または ResourceObject)を残すか、announce 側で解決する。 - -### タグと TTL のどちらが要るかは、ログでは決まらない - -タグだけ宣言しても、**そのタグを announce する書き込み経路がある値**しか新しく保てない。body に他所の値を -コピーしていて announce 経路が無ければ、タグは届かず TTL だけが床になる。コードに問う: - -1. この body に入る値ごとに、**それを変える書き込み経路**は何か -2. その経路は invalidate を呼ぶか(呼ばないなら TTL が唯一の eviction) -3. 同じデータの**別の複製**があるなら、複製の寿命は原本以下か(長いと、原本が捨てた値を複製が返す) - -3 は attribute から機械的に検査できる。実例: -[BeMart `tests/Resource/AgentCorpusCacheTest.php`](https://github.com/be-framework/BeMart/blob/1.x/tests/Resource/AgentCorpusCacheTest.php) - -## 5. 切り分け — アプリの問題か、ライブラリの問題か - -ログは「何が起きたか」を言うが、「誰の落ち度か」は言わない。**先に観測で候補を 1 つに絞り、 -それから該当行の変数を見る**。順番を逆にすると、写しを覗くだけで終わる。 - -| 観測 | アプリ側 | ライブラリ側 | 決め手 | -|---|---|---|---| -| ログが空(miss すら無い) | `final`(`ReflectionClass::isFinal()` が true)、属性そのものが無い、文脈が店を束縛していない | sink が arm を拒否 | 織られたか(`get_class`)→ 真なら `isFinal()` と属性の有無で二分 / `error_log` | -| 期待した `save_*` が無い | `put_skipped` の `reason` がアプリ由来(自前 ETag・非 200) | `put_skipped` も無いのに保存されない | `put_skipped` の有無と `reason` | -| `save_*` の `tags` に子が無い | 値をコピーしている(`#[Embed]` でない) | `depends_on` はあるのにタグが乗らない = 伝播の欠陥(`CacheDependency::depends()` が親の `Surrogate-Key` に子タグを積む) | `depends_on` イベントの有無 | -| 書き込みが `invalidate` を出さない | 書き込み経路に `#[Refresh]`/`#[Purge]` が無い | 属性はあるのにマッチャがそのメソッドを拾わない | 織られたオブジェクトの `bindings` にそのメソッドがあるか | -| `invalidate` は出るが親が hit のまま | タグの選び方が違う(URI タグと共有サロゲートキーの混同) | タグ集合の交差計算の欠陥 | 2 つのタグ集合を並べて交わりを見る | -| `invalidate` のタグがどのリソースの宣言とも一致しない | **手書きの `invalidateTags()` が定数からドリフトしている** — リソースは `SURROGATE_KEY` 定数を宣言し、無効化側は生文字列を持ったまま取り残された | — | `invalidate` の `tags` を、リソースが宣言する定数の実値と 1 文字ずつ突き合わせる。docblock だけ正しいことがある | -| 値が古い | TTL が床(設計判断) | — | `save_*` の `ttl` | -| `cache_error` / `pool_error` | 店の設定・接続 | 縮退の扱い | 例外か縮退かは `docs/what-the-log-proves.md` | - -**「ライブラリ側」に振った候補が 1 つ残ったときだけ**、該当クラスの分岐を観測する。道具は -`koriym/xdebug-mcp`(`composer global require koriym/xdebug-mcp`)。**php 本体に Xdebug が入っていなくてよい** -— ラッパーが自分で読み込む。**vendor は既定で記録から除外される**ので、明示して入れる: - -```bash -# 1) どの分岐まで届いているか(--include-vendor が無いとライブラリのフレームは空) -xtrace --include-vendor="bear/query-repository" --context="tags absent from parent save" -- php repro.php - -# 2) 判断している行を名前で探す(行番号は版ごとに動く) -grep -n "SURROGATE_KEY" vendor/bear/query-repository/src/CacheDependency.php - -# 3) その行で実引数を見る -xstep --break="vendor/bear/query-repository/src/CacheDependency.php:" \ - --steps=20 --context="what tags arrive" -- php repro.php -``` - -`xtrace` はスクリプトの stdout をそのまま流し、**トレース自体は `/tmp/trace.*.xt` に書いて**末尾に場所と -規模を出す(実測: 1 リクエストで 63688 行 / 534 関数)。読むのはそのファイルで、全部は読まない — -`--context` に何を見たいかを書き、ファイルは目的の関数名で `grep` する。 - -**`xstep` の前に、ライブラリの既存テストを 1 本走らせる。** 同じシナリオを守るテストが既に赤なら、 -切り分けはそこで終わる(実測: `--filter testMultipleParentsDependOnSameChild tests/CacheDependencyTest.php` -が伝播の欠陥をそのまま赤で再現した)。スイート全体は走らせない。 - -判断点の在処: `CacheInterceptor`(hit/miss と保存)、`CommandInterceptor`(書き込み後の無効化)、 -`QueryRepository`(put/get/purge)、`ResourceStorage`(タグと 2 プール)、`CacheDependency`(依存の伝播)、 -`DonutRepository`(donut)、`HttpCache` / `CliHttpCache`(304 判定)、`EtagSetter`(ETag 生成)。 - -**`var_dump` / `printf` を仕込まない。** 使い捨てスクリプトに同じロジックを書き写して覗くのは、対象ではなく -写しを見ている(写し間違いに気づけない)。`bin/repro.php` は**対象を呼ぶだけ**にする。 - -## 6. 報告 - -切り分けの結論は、次の 6 つで書く。1 つでも欠けたら、まだ報告できていない: - -1. **どちらの問題か** — アプリ / ライブラリ / 設計判断のどれか -2. **観測の根拠** — イベント列の抜粋(`save_value{tags: [...]}` → `invalidate{tags: [...]}` の形)と、 - ライブラリを疑うなら `xstep` で見た実引数。「トレースした」と書くのは実際にツールを使ったときだけ -3. **最小再現** — 対象を呼ぶだけのスクリプトかテスト 1 本 -4. **ユーザーが何を感じるか** — 「在庫が最大 60 秒古い」のように、外から見える言葉で -5. **修正の証明** — 直したなら、**どのイベントがどう変わったかをログで示す**。テストが緑になったことは - 証明ではない(テストは同じ盲点を持ち得る) -6. **既存の検証はこれを検出できたか** — テスト・オラクル・CI を実際に走らせて答える。緑だったなら - **その検証がアプリのコードパスを通っているか**を確かめる。ライブラリの同じ能力を直接叩いて - 代替検証しているだけなら、アプリ側の誤りは原理的に見えない(実例: オラクルが `purgeTags` を - `ResourceStorageInterface::invalidateTags()` に直接渡すと、アプリの無効化サービスを一度も通らない) - -**ライブラリだと言うなら、ライブラリの fixture で落ちるテストを添える。添えられないなら、 -まだアプリ側の疑いに戻す。** - -## 7. トラブルシュート定型 - -- **「キャッシュが効いていない」**: 対象 URI の `get` スコープ。`cache_hit` で閉じていれば効いている。 - `put_skipped{etag-present}` なら自前 ETag、`put_skipped{error-code}` なら非 200 -- **「purge したのに古い」**: `invalidate` の `tags` に対象キーがあるか。`cdn: skipped` は purger 未設定 - (ローカルだけ消えて CDN に残る)、`cdn: failed` なら例外が伝播しているはず(fail-closed) -- **「CDN が長く持ちすぎる」**: `cdn_headers.headers` の lifetime ヘッダ。`sMaxAge` 未指定の既定値 - (generic 10 秒 / Fastly・Akamai 31536000 秒)が原因のことが多い -- **「304 が返らない」**: `conditional_request` が `cache_miss{layer: etag}` で閉じていれば検証子が古い。 - スコープ自体が無ければ `If-None-Match` が届いていない(プロキシ・FW を疑う) -- **「何も効いていない(毎回リソースが走り、ETag も `Cache-Control` も付かない)」**: 部分的な失敗ではない。 - `get` スコープが 0 件なら織られていない(§2)。属性を消したのと同じ状態で、キャッシュ以外は正常に動く - -## 範囲外(ログに聞いても無駄) - -CDN 側の実挙動(伝播遅延・エッジ側 eviction)、`#[HttpCache]` の静的ヘッダ設定、独自ヘッダ名のカスタム -setter、実時間での期限消滅。詳細は `what-the-log-proves.md` の "What the log does not record"。