Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
## [Unreleased]

### Added
- The dependency evidence in `docs/reading-the-log.md` is now stated per parent declaration (`#[Cacheable]` / `#[CacheableResponse]` / `#[DonutCache]`), pinned by `DonutDependencyEvidenceTest` (#188).
- `UriScopedHttpCacheInterface::isNotModifiedFor($uri, $server)` and `ScopedValidatorInterface::hasEtagFor($etag, $uri)`: the conditional-request answer, scoped to the resource that was asked for (#197). `HttpCacheInterface::isNotModified()` receives the request environment and nothing else, so it can only ask whether the offered validator is alive somewhere in the pool - a client or intermediary returning a validator it holds for another URI was answered 304 about content this server never sent it. An application opts in by routing before the check; routing costs a path match, not a resource run. The ETag entry now stores the URI tag it was issued for, where it used to store the constant `etag`: entries written by an older version cannot be scoped, so each client pays one full response after the upgrade, once. The unscoped method is unchanged.
- `durationMs` on the `cache_hit` / `cache_miss` **close**: what the answer cost. A hit close measures serving from the pool, a miss close measures the resource run and the write it triggered, so the pair is what says whether the cache is worth having - the sign, not the difference, since a miss includes the fill. A bare event (`layer: donut`) carries null: no scope, nothing to measure. Every other question the log answers is about correctness; this is the first one about cost.
- Cache observability is now built on [Koriym.SemanticLogger](https://github.com/koriym/Koriym.SemanticLogger): an open/event/close tree whose nesting **is** the embed/dependency structure (a parent's embedded children nest under it). Typed `AbstractContext` subclasses live in `src/Log/Context/` with per-context JSON Schemas in `docs/schemas/context/`.
Expand Down
4 changes: 2 additions & 2 deletions docs/llms-full.txt
Original file line number Diff line number Diff line change
Expand Up @@ -186,7 +186,7 @@ Cache operations are logged as an open/event/close tree (Koriym.SemanticLogger)
| `get` | open | A resource/donut GET scope; embedded child GETs nest under it |
| `cache_hit` / `cache_miss` (`layer`) | close/event | Lookup outcome (`layer`: `resource` / `donut` / `donut-view` / `etag`) |
| `command` (`method`/`annotations`/`source`) | open | A write scope; `source` names the producing interceptor, `annotations` its `#[Refresh]`/`#[Purge]` attributes (empty on the CacheableResponse path by design) |
| `depends_on` (`parent`/`child`/`childTags`) | event | Parent registered a dependency on a child's tags |
| `depends_on` (`parent`/`child`/`childTags`) | event | Parent registered a dependency on a child's tags. Written by `QueryRepository::put()` only, so a `#[Cacheable]` parent records it (its child tags land on `save_value`/`save_view` and `save_etag`) and a donut parent never does: a `#[CacheableResponse]` parent's child tags show up on `save_etag`/`save_donut_view` (never on `save_donut`), a `#[DonutCache]` parent's only in `cdn_headers.surrogateKeys` |
| `save_value` / `save_view` / `save_etag` / `save_donut` / `save_donut_view` | event | What was stored, with `tags`, `requestedTtl` (seconds until expiry; 0/null = no expiry set), and the `saved` outcome |
| `pre_write_cleanup` (`uri`) | event | Marker recorded by a writer right before it clears the entry it is about to rewrite; the `invalidate` immediately following it in the same scope is pre-write cleanup, not a real invalidation |
| `invalidate` (`tags`/`roPool`/`etagPool`/`cdn`/`durationMs`) | event | Tag invalidation outcome; `cdn` is tri-state: `purged` (a configured purger ran), `failed` (the purge threw — fail-closed, after the local pools were invalidated), `skipped` (NullPurger, no CDN configured). Pre-write cleanup vs real invalidation is recorded at the source via the `pre_write_cleanup` marker — see below |
Expand Down Expand Up @@ -214,7 +214,7 @@ A donut refresh is not marked in any response header — only in the log (`refre

### Verifying the event-driven cache from logs

- Event-driven entries appear with their configured TTL in seconds (`requestedTtl` = seconds until expiry; the `never` convention = 31536000 = 1 year, effectively indefinite). `0`/`null` also mean no expiry is set. Such entries live until an `invalidate` event with a matching tag — correlate `save_*` `tags` with `invalidate` `tags` to confirm a write busted its dependents.
- Event-driven entries appear with their configured TTL in seconds (`requestedTtl` = seconds until expiry; the `never` convention = 31536000 = 1 year, effectively indefinite). `0`/`null` also mean no expiry is set. Such entries live until an `invalidate` event with a matching tag — correlate `save_*` `tags` with `invalidate` `tags` to confirm a write busted its dependents. Which `save_*` carries a child's tags is decided by the parent's declaration: `#[Cacheable]` puts them on `save_value`/`save_view` and `save_etag`, records a `depends_on` edge as well, and the parent closes `cache_miss` once the child is purged; `#[CacheableResponse]` records no `depends_on`, tags `save_etag`/`save_donut_view` but never `save_donut` (the shell has to outlive the child), and after a child purge still closes `cache_hit{layer: donut-view}` with a `refresh_donut` inside — a hit with no `refresh_donut` is the stale shape; `#[DonutCache]` stores no child tag at all (they reach only `cdn_headers.surrogateKeys`) and every read after the first is `refresh_donut` + `put_skipped{not-cacheable}`.
- A `get` scope with no events and a `cache_hit` close was served from cache; nesting mirrors the embed structure of resources; `manual_*` scopes mark non-AOP entry points — a direct `put()`, `purge()`, `invalidateTags()` or donut write (`putStatic()`/`putDonut()`), the whole write rooted in one `manual_store` scope.
- A miss scope without `save_*` events means no put happened — look for a `put_skipped` event recording why (`reason`: `etag-present`, `error-code` with the actual response `code`, or `not-cacheable` for donut pages served from their template plus inner caches). A non-200 GET yields `put_skipped{error-code, code}` + `purge` + `invalidate` (for commands, a 4xx `command_result` with no invalidation events).
- An `invalidate` is pre-write cleanup iff the event immediately preceding it in the same scope's event stream is a `pre_write_cleanup` marker — the writer records the purpose at the source (`QueryRepository::doPut()` and `DonutRepository::putStatic()`/`putDonut()` emit the marker right before clearing the entry they are about to rewrite), so nothing is inferred from tag correlation and no case is undecidable. Any `invalidate` without the marker is a real invalidation (a `#[Refresh]` command shows both shapes: the purge's invalidate has no marker, the re-put's deleteEtag is marker-preceded). The cleanup uses the resource's own URI tag — which is also its parents' surrogate key — so a child refill visibly purges the parent entry, by design.
Expand Down
2 changes: 1 addition & 1 deletion docs/llms.txt
Original file line number Diff line number Diff line change
Expand Up @@ -45,7 +45,7 @@ Cache operations are logged as an open/event/close tree (Koriym.SemanticLogger)

Verifying the event-driven cache from logs:

- Event-driven entries appear with their configured TTL in seconds (`requestedTtl` = seconds until expiry; the `never` convention = 31536000 = 1 year, effectively indefinite). `0`/`null` also mean no expiry is set. Such entries live until an `invalidate` event with a matching tag — correlate `save_*` `tags` with `invalidate` `tags` to confirm a write busted its dependents.
- Event-driven entries appear with their configured TTL in seconds (`requestedTtl` = seconds until expiry; the `never` convention = 31536000 = 1 year, effectively indefinite). `0`/`null` also mean no expiry is set. Such entries live until an `invalidate` event with a matching tag — correlate `save_*` `tags` with `invalidate` `tags` to confirm a write busted its dependents. Which `save_*` carries a child's tags is decided by the parent's declaration: `#[Cacheable]` puts them on `save_value`/`save_view` and `save_etag`, records a `depends_on` edge as well, and the parent closes `cache_miss` once the child is purged; `#[CacheableResponse]` records no `depends_on`, tags `save_etag`/`save_donut_view` but never `save_donut` (the shell has to outlive the child), and after a child purge still closes `cache_hit{layer: donut-view}` with a `refresh_donut` inside — a hit with no `refresh_donut` is the stale shape; `#[DonutCache]` stores no child tag at all (they reach only `cdn_headers.surrogateKeys`) and every read after the first is `refresh_donut` + `put_skipped{not-cacheable}`.
- `cdn_headers` records the CDN-facing response headers verbatim at every donut write/refresh (`headers`: literal name => value, e.g. `CDN-Cache-Control`/`Surrogate-Control`/`Akamai-Cache-Control` and `Surrogate-Key`/`Edge-Cache-Tag`; `surrogateKeys`: the split purge-key list). The bound setter's default appears here even when `put_donut` says `sMaxAge: null`; no lifetime header in the map = the response gave the CDN no lifetime directive (the `putDonut` kind); the CDN's own behavior is outside this log. Correlate `invalidate` `tags` with `surrogateKeys` to confirm a purge reached the responses the CDN holds.
- A `conditional_request` scope closing `cache_hit{layer: etag}` is the 304 decision: the whole request answered from the ETag pool without running the resource (`cache_miss{layer: etag}` = the validator is stale, a full response follows).
- A `get` scope with no events and a `cache_hit` close was served from cache; nesting mirrors the embed structure of resources; `manual_*` scopes mark non-AOP entry points — a direct `put()`, `purge()`, `invalidateTags()` or donut write (`putStatic()`/`putDonut()`), the whole write rooted in one `manual_store` scope.
Expand Down
15 changes: 14 additions & 1 deletion docs/reading-the-log.ja.md
Original file line number Diff line number Diff line change
Expand Up @@ -95,7 +95,7 @@ get page://self/html/blog-posting ← スコープ: open されて clos
| `put_donut` | `uri`, `requestedTtl`, `sMaxAge` | donut の書き込みを要求した。要求時の lifetime つき |
| `refresh_donut` | `uri` | キャッシュ済み donut をそのまま返さず再合成した |
| `cdn_headers` | `uri`, `headers`, `surrogateKeys` | 応答に実際に付いた CDN 向けヘッダ |
| `depends_on` | `parent`, `child`, `childTags` | 依存の辺 1 本。子のタグが親に加わった |
| `depends_on` | `parent`, `child`, `childTags` | 依存の辺 1 本。子のタグが親に加わった。記録するのは `#[Cacheable]` の put だけ |
| `pre_write_cleanup` | `uri` | 書き込み側が、上書きするエントリを消す直前 |
| `invalidate` | `tags`, `roPool`, `etagPool`, `cdn`, `durationMs` | タグを無効化した。対象ごとの結果つき |
| `purge` | `uri` | URI 指定の破棄を要求した |
Expand Down Expand Up @@ -179,6 +179,17 @@ get page://self/html/blog-posting ← スコープ: open されて clos
突き合わせます。交差しないタグは、その書き込みがそのエントリを残したことを意味します — これが
内側から見た「stale を配信している」状態です。

**子のタグがどのエントリに載るかは、親の宣言で決まります。** `#[Cacheable]` の親は `depends_on` の辺を
記録し、子のタグを自分の `save_value`/`save_view` と `save_etag` に載せます。だから子を purge すると
親のエントリも一緒に消え、次の read は `cache_miss` で閉じます。`#[CacheableResponse]` の親は
`depends_on` を出しません — donut の書き込みは `put()` を通らないからです。子のタグは `save_etag` と
`save_donut_view` に載り、`save_donut` には載りません。殻は子より長く生きて再合成の土台になるからです。
子を purge した後もこの親は `cache_hit{layer: donut-view}` で閉じ、中に `refresh_donut` と新しい
`save_etag`/`save_donut_view` があります。この hit が健全な形で、stale は `refresh_donut` の無い
`cache_hit` です。`#[DonutCache]` の親は子のタグをどこにも保存しません — `cdn_headers.surrogateKeys`
まで届いて、そこで終わりです。2 回目からの read は毎回、`refresh_donut` のあとに
`put_skipped{reason: not-cacheable}` が続きます。子を purge して変わるのは、入れ子の `get` だけです。

**エントリが期限切れになる設計かどうかは、TTL ではなく `cache_policy.expiry` を読みます。**
`expiry: "never"` は「無効化が届くまで」という意図です。解決した数値は保険であり、アプリが `Expiry` を
どう束縛したかで変わります — 既定のインストールでは `never` が 31536000 秒になり、意図的な 1 年 TTL と
Expand Down Expand Up @@ -226,6 +237,8 @@ ETag プールだけでリクエスト全体に答えています。304 が現

**donut の `cache_hit` に出るのは最終層です。** ページがキャッシュから来たのか、出力の途中で
再合成されたのかはスコープの中にあります — `refresh_donut` イベントがあれば再合成です。
子を purge した後の `#[CacheableResponse]` の親がまさにこの形です。残っていたテンプレートが read を
hit にし、中身を新しくするのは再合成のほうです。

## 実例

Expand Down
19 changes: 17 additions & 2 deletions docs/reading-the-log.md
Original file line number Diff line number Diff line change
Expand Up @@ -97,7 +97,7 @@ operation inside a GET or a command is an ordinary event there instead.
| `put_donut` | `uri`, `requestedTtl`, `sMaxAge` | a donut write was requested, with the lifetime asked for |
| `refresh_donut` | `uri` | a cached donut was recomposed rather than served as-is |
| `cdn_headers` | `uri`, `headers`, `surrogateKeys` | the CDN-facing headers the response actually carried |
| `depends_on` | `parent`, `child`, `childTags` | one dependency edge: the child's tags were added to the parent |
| `depends_on` | `parent`, `child`, `childTags` | one dependency edge: the child's tags were added to the parent. Only a `#[Cacheable]` put records one |
| `pre_write_cleanup` | `uri` | the writer is about to clear the entry it will rewrite |
| `invalidate` | `tags`, `roPool`, `etagPool`, `cdn`, `durationMs` | tags were invalidated, with a result per target |
| `purge` | `uri` | a URI-targeted bust was requested |
Expand Down Expand Up @@ -185,6 +185,19 @@ 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.

**Which entry carries a child's tags is decided by the parent's declaration.** A `#[Cacheable]`
parent records a `depends_on` edge and puts the child's tags on its `save_value`/`save_view` and
`save_etag`, so purging the child takes the parent's entry with it and the next read closes
`cache_miss`. A `#[CacheableResponse]` parent records no `depends_on` — the donut writer never
calls `put()` — and puts the child's tags on `save_etag` and `save_donut_view` but deliberately not
on `save_donut`, the shell that has to outlive the child. After the child is purged that parent
still closes `cache_hit{layer: donut-view}`, with a `refresh_donut` and a fresh
`save_etag`/`save_donut_view` inside: that is the healthy shape, and stale is a `cache_hit` with no
`refresh_donut` in it. A `#[DonutCache]` parent stores no child tag anywhere — they reach
`cdn_headers.surrogateKeys` and stop there — so every read after the first is `refresh_donut`
then `put_skipped{reason: not-cacheable}`, and purging the child changes only the child's own
nested `get`.

**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
Expand Down Expand Up @@ -234,7 +247,9 @@ validator was issued for the resource that was requested, which is the question
poses; an application gets it by routing first, which costs a path match and not a resource run.

**A donut `cache_hit` reports the final layer.** Whether the page came from the cache or was
recomposed on the way out is inside the scope: a `refresh_donut` event means recomposed.
recomposed on the way out is inside the scope: a `refresh_donut` event means recomposed. A
`#[CacheableResponse]` page read after its child was purged is exactly that shape — the template it
kept makes the read a hit, and the recomposition is what makes the page fresh.

## Worked example

Expand Down
22 changes: 22 additions & 0 deletions tests/CACHE_DEPENDENCY_TESTS.md
Original file line number Diff line number Diff line change
Expand Up @@ -78,6 +78,24 @@ purge(Comment) → BlogPosting invalidated

**Test:** `DonutRepositoryTest::testCacheDependency`

Which log entry carries the child's tags — and so what the parent's next read looks like — is
decided by the parent's cache declaration, not by the embed:

| Parent declaration | Child tags recorded on | Parent's read after the child is purged |
|---|---|---|
| `#[Cacheable]` | `depends_on`, `save_value`/`save_view`, `save_etag` | `cache_miss{layer: resource}` |
| `#[CacheableResponse]` | `save_etag`, `save_donut_view`, never `save_donut` | `cache_hit{layer: donut-view}` holding a `refresh_donut` |
| `#[DonutCache]` | `cdn_headers.surrogateKeys` only | unchanged: `refresh_donut` + `put_skipped{not-cacheable}` |

**Tests:** `DonutDependencyEvidenceTest` — `testCacheableParentRecordsADependsOnEdge`,
`testCacheableParentTagsValueAndEtagWithTheChild`,
`testCacheableParentMissesAfterItsChildIsPurged`,
`testCacheableResponseWriteRecordsNoDependsOnEdge`,
`testCacheableResponseTagsEtagAndViewWithTheChildButNotTheTemplate`,
`testCacheableResponseRebuildsFromItsTemplateAfterTheChildIsPurged`,
`testDonutCacheKeepsTheChildTagsOutOfTheStore`,
`testDonutCacheReadShapeIsUnchangedByPurgingTheChild`

### Tag-Based Invalidation

Resources can be invalidated by their URI-derived tags.
Expand Down Expand Up @@ -266,6 +284,10 @@ All dependency tests verify both resource cache and ETag invalidation:
`refresh_donut` event inside the scope; the close label is intentionally coarse.
When the page is not entire-content cacheable, no page-level save follows the
rebuild — recorded as `put_skipped` with `reason=not-cacheable`.
A `#[CacheableResponse]` page read right after its child was purged is this shape, so a
reader expecting the `#[Cacheable]` shape (`cache_miss`) reads a healthy rebuild as a stale
serve. The stale shape is a `cache_hit` with no `refresh_donut` in it
(`DonutDependencyEvidenceTest::testCacheableResponseRebuildsFromItsTemplateAfterTheChildIsPurged`).
- **Legacy `RepositoryLoggerInterface` receives no events.** Internal cache code logs
through `SemanticLoggerInterface`; the deprecated flat interface stays bound for code
BC but its instance stays empty. Consumers should migrate to the SemanticLogger tree.
Expand Down
Loading
Loading