diff --git a/CHANGELOG.md b/CHANGELOG.md index 9f1777f3..b6ffeb4b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,41 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [Unreleased] + +### Added +- 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/`. +- `SafeSemanticLogger` (best-effort decorator) guarantees logging never breaks cache reads/writes. The DI default bound via `SafeSemanticLoggerProvider` in `DonutCacheModule` is `SafeSemanticLogger(new SemanticLogger())`; `NullSemanticLogger` is the constructor-parameter fallback when no logger is injected. +- `invalidate` context records per-target outcomes as self-describing status words: `roPool`/`etagPool` (`invalidated`|`failed`), `cdn` (`purged`|`failed`), plus `durationMs`. A CDN purge failure is fail-closed: the local pools are invalidated first and the outcome is logged as `cdn: failed`, then the purge exception propagates so a write does not silently leave stale CDN content. +- Logs validate against their schemas in tests via `SemanticLogValidator` (`SemanticLogTreeTrait`), and `vendor/bin/stree` renders the cache log as a readable tree (`demo/run-dependency.php`, `demo/run-donut.php`). +- Direct (non-AOP) top-level `put()`, `purge()` and `invalidateTags()` calls are rooted in `manual_store` / `manual_purge` / `manual_invalidate` scopes so their save/purge/invalidate events stay visible; an event with no enclosing scope would otherwise be dropped at flush. +- `cache_error` context: emitted when the cache layer itself throws (e.g. cache server down) in the read/write interceptors, so a cache outage is distinguishable from a genuine cold-cache miss in the log. +- `saved` outcome field on the save contexts (`save_value` / `save_view` / `save_donut` / `save_donut_view` / `save_etag`): the cache pool's accept/reject result, so a silently failed store no longer looks like a successful save. +- `tags` (invalidation tags) on all five save contexts, so a save can be correlated with the `invalidate` events that later bust it. +- `put_skipped` context: emitted when a miss is not followed by a put, so a miss without save events reads as a recorded skip, not a lost write. `reason` is `etag-present`, `error-code` (with the actual response `code`, also emitted by `CacheInterceptor` on a non-200 GET), or `not-cacheable` (a donut page re-rendered from its template is never stored as a rendered page). +- `source` field on the `command` context naming the producing interceptor (`CommandInterceptor` / `DonutCommandInterceptor` / `RefreshInterceptor`). +- `operation` field on `cache_error` (`read` / `write`), so the failing side of a degraded cache layer is recorded. +- `cdn` on `invalidate` is now tri-state: `purged` (a configured purger ran), `failed` (it threw), `skipped` (the bound purger is `NullPurger`, i.e. no CDN configured) — previously a no-op NullPurger was indistinguishable from a real purge (`purged`). +- `ttl` field on `save_etag`, completing the save contexts; all `ttl` descriptions state the convention that 31536000 is the `never` expiry placeholder and event-driven invalidation is the intended eviction path. +- `log_session_broken` sentinel: when `SafeSemanticLogger` must discard a broken logging session (e.g. a LIFO violation), the recovery flush returns this scope carrying the cause instead of a silent empty log — "no records" is never misread as "no cache activity". +- Negative TTL clamping: a past `expiryAt` or a negative `expirySecond`/ttl argument is clamped to 0 at the `QueryRepository`/`ResourceStorage` boundary, matching the `"minimum": 0` the schemas declare. +- The demos verify themselves: all three scripts print the semantic log (tree + pretty JSON) and validate the flushed session offline against `docs/schemas/context`, printing a one-line verdict and exiting non-zero on any violation. `demo/run-dependency.php` scenario 3 is now command-driven — a PUT on `LevelThree` (whose new `onPut` carries `#[Purge]`) opens a `command` scope whose purge cascades to level-two/level-one — alongside the manual `manual_purge` entry kind in scenario 6. `demo/run.php` binds real in-memory pools so its log shows genuine cache hits (the `QueryRepositoryModule` default `NullAdapter` made every GET miss). + +### Deprecated +- `RepositoryLogger`, `RepositoryLoggerInterface`, `StructuredRepositoryLoggerInterface` and `NullRepositoryLogger`. Internal cache code now logs through `Koriym\SemanticLogger\SemanticLoggerInterface`; the legacy flat interface remains bound for BC but receives no internal events. + +### 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). + +### Changed +- Cache logging call sites (`QueryRepository`, `ResourceStorage`, `DonutRepository`, `CacheInterceptor`, `AbstractDonutCacheInterceptor`, `CommandInterceptor`, `RefreshInterceptor`) now emit typed contexts through `SemanticLoggerInterface` instead of `RepositoryLoggerInterface::log()`. +- `SaveDonutContext`/`SaveDonutViewContext`: the misleading `sMaxAge` field is renamed to `ttl` — the value is the cache entry TTL, never a CDN s-maxage. +- `SaveEtagContext`/`SaveDonutViewContext`: `surrogateKeys` renamed to `tags`; all save contexts now consistently report invalidation tags under `tags`. +- Command scopes are opened even for failed writes: a 4xx response closes with `command_result` (code 4xx) and no invalidation events, recording that the purge/refresh was correctly skipped instead of vanishing from the log. +- Removed the post-save `assert()` in `ResourceStorage::saveDonut()`: with assertions enabled it threw AFTER the `saved: false` event was logged, contradicting quiet-failure recording. +- The pre-write-cleanup rule for `invalidate` events is redefined as a machine-applicable predicate: an invalidate is pre-write cleanup when, within the SAME scope's event stream, a later `save_*` event's tags include the invalidate's tags — regardless of the enclosing scope type (a `#[Refresh]` command's second put runs inside the command scope, and `depends_on` events may sit between the cleanup invalidate and the saves). In donut scopes match against `save_etag`/`save_donut_view` (`save_donut`'s tags may exclude the URI tag). This supersedes the earlier scope-type/"immediately followed" formulation in the schemas and guides. +- Added runtime dependency `koriym/semantic-logger`. + ## [1.16.2] - 2026-06-29 ### Fixed diff --git a/CLAUDE.md b/CLAUDE.md index 299f2cac..e908ec40 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -207,4 +207,4 @@ Follows PSR-12 coding standards with PHP_CodeSniffer. - BEAR.Sunday LLM docs: https://bearsunday.github.io/llms-full.txt - This package LLM docs: https://bearsunday.github.io/BEAR.QueryRepository/llms-full.txt - Cache manual: https://bearsunday.github.io/manuals/1.0/en/cache.html -- Log schema: https://bearsunday.github.io/BEAR.QueryRepository/schemas/repository-log.json \ No newline at end of file +- Log schemas: https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/ (one JSON Schema per log context, e.g. https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/save_value.json) \ No newline at end of file diff --git a/composer.json b/composer.json index 4a4051c2..ab7b9a59 100644 --- a/composer.json +++ b/composer.json @@ -18,6 +18,7 @@ "php": "^8.2", "bear/resource": "^1.16.1", "bear/sunday": "^1.5", + "koriym/semantic-logger": "^0.8.0", "psr/cache": "^1.0 || ^2.0 || ^3.0", "ray/aop": "^2.19.1", "ray/di": "^2.20", diff --git a/demo/AppModule.php b/demo/AppModule.php index 7c382315..9d2c5581 100644 --- a/demo/AppModule.php +++ b/demo/AppModule.php @@ -5,9 +5,13 @@ namespace FakeVendor\DemoApp; use BEAR\QueryRepository\QueryRepositoryModule; +use BEAR\RepositoryModule\Annotation\EtagPool; +use BEAR\RepositoryModule\Annotation\ResourceObjectPool; use BEAR\Resource\Module\ResourceModule; use Ray\Di\AbstractModule; use Ray\Di\Scope; +use Symfony\Component\Cache\Adapter\AdapterInterface; +use Symfony\Component\Cache\Adapter\ArrayAdapter; class AppModule extends AbstractModule { @@ -19,5 +23,9 @@ protected function configure() $this->bind()->annotatedWith('storage_dir')->toInstance(__DIR__ . '/tmp')->in(Scope::SINGLETON); $this->install(new ResourceModule(__NAMESPACE__)); $this->install(new QueryRepositoryModule); + // Real in-memory pools: QueryRepositoryModule's default is a NullAdapter, + // under which every demo GET would miss and the log could never show a hit. + $this->bind(AdapterInterface::class)->annotatedWith(ResourceObjectPool::class)->to(ArrayAdapter::class); + $this->bind(AdapterInterface::class)->annotatedWith(EtagPool::class)->to(ArrayAdapter::class); } } diff --git a/demo/run-dependency.php b/demo/run-dependency.php index 62e6ba87..d60a965b 100644 --- a/demo/run-dependency.php +++ b/demo/run-dependency.php @@ -8,7 +8,9 @@ * This script demonstrates cache dependency logging to help understand: * - Cache hit/miss operations * - Dependency registration (depends-on) + * - Command-driven invalidation (a #[Purge] write opens a command scope) * - Cascade invalidation (invalidate-etag) + * - Manual purge (a direct purge() call roots a manual_purge scope) * * Resources used (from tests/Fake/fake-app): * - LevelOne -> LevelTwo -> LevelThree (3-level dependency chain) @@ -18,12 +20,15 @@ use BEAR\QueryRepository\FakeEtagPoolModule; use BEAR\QueryRepository\ModuleFactory; use BEAR\QueryRepository\QueryRepositoryInterface; -use BEAR\QueryRepository\RepositoryLoggerInterface; use BEAR\Resource\ResourceInterface; use BEAR\Resource\Uri; +use Koriym\SemanticLogger\SemanticLoggerInterface; +use Koriym\SemanticLogger\Stree\RenderConfig; +use Koriym\SemanticLogger\Stree\TreeRenderer; use Ray\Di\Injector; require dirname(__DIR__) . '/vendor/autoload.php'; +require __DIR__ . '/validate.php'; // Scenario descriptions (for humans) echo <<<'SCENARIOS' @@ -38,17 +43,22 @@ 2. Re-access level-one - Should be cache-hit -3. Purge level-three (grandchild) - - Should cascade invalidate level-two and level-one +3. Write to level-three (PUT) + - #[Purge] on LevelThree::onPut invalidates level-three's cache + - The surrogate-key cascade busts level-two and level-one + - The log shows a command scope (method/annotations/source) + driving the purge — cause and effect in one subtree -4. Re-access level-one after purge +4. Re-access level-one after the write - All three should be cache-miss (regenerated) 5. Access ParentA and ParentB - Both embed ChildC (shared dependency) -6. Purge child-c +6. Purge child-c (manual repository purge) - Should invalidate both ParentA and ParentB + - A direct purge() roots a top-level manual_purge scope — + a different entry kind than the command scope in 3 7. Re-access both parents after purge - Both should be cache-miss (regenerated) @@ -65,36 +75,31 @@ $resource = $injector->getInstance(ResourceInterface::class); $repository = $injector->getInstance(QueryRepositoryInterface::class); -$logger = $injector->getInstance(RepositoryLoggerInterface::class); - -// Execute scenarios silently -$logger->log('request-start', ['uri' => 'page://self/dep/level-one']); -$resource->get('page://self/dep/level-one'); // 1. Initial access - -$logger->log('request-start', ['uri' => 'page://self/dep/level-one']); -$resource->get('page://self/dep/level-one'); // 2. Re-access (cache-hit) - -$logger->log('request-start', ['uri' => 'page://self/dep/level-three', 'method' => 'purge']); -$repository->purge(new Uri('page://self/dep/level-three')); // 3. Purge grandchild - -$logger->log('request-start', ['uri' => 'page://self/dep/level-one']); -$resource->get('page://self/dep/level-one'); // 4. Re-access after purge - -$logger->log('request-start', ['uri' => 'page://self/dep/parent-a']); -$resource->get('page://self/dep/parent-a'); // 5a. Access ParentA - -$logger->log('request-start', ['uri' => 'page://self/dep/parent-b']); -$resource->get('page://self/dep/parent-b'); // 5b. Access ParentB - -$logger->log('request-start', ['uri' => 'page://self/dep/child-c', 'method' => 'purge']); -$repository->purge(new Uri('page://self/dep/child-c')); // 6. Purge shared child - -$logger->log('request-start', ['uri' => 'page://self/dep/parent-a']); -$resource->get('page://self/dep/parent-a'); // 7a. Re-access ParentA - -$logger->log('request-start', ['uri' => 'page://self/dep/parent-b']); -$resource->get('page://self/dep/parent-b'); // 7b. Re-access ParentB - -// Output logs only -echo "=== Cache Log ===" . PHP_EOL; -echo $logger . PHP_EOL; +$logger = $injector->getInstance(SemanticLoggerInterface::class); + +// Execute scenarios. Embedded child GETs nest under their parent GET, so the +// log's open/close tree IS the embed/dependency tree (no reconstruction). +$resource->get('page://self/dep/level-one'); // 1. Initial access (cache-miss chain) +$resource->get('page://self/dep/level-one'); // 2. Re-access (cache-hit) +$resource->put('page://self/dep/level-three'); // 3. Write: #[Purge] command (cascade) +$resource->get('page://self/dep/level-one'); // 4. Re-access after the write (rebuilt) +$resource->get('page://self/dep/parent-a'); // 5a. Access ParentA +$resource->get('page://self/dep/parent-b'); // 5b. Access ParentB +$repository->purge(new Uri('page://self/dep/child-c')); // 6. Manual purge (manual_purge scope) +$resource->get('page://self/dep/parent-a'); // 7a. Re-access ParentA +$resource->get('page://self/dep/parent-b'); // 7b. Re-access ParentB + +$log = $logger->flush(); + +// Human/AI-readable tree (open = embed scope, close = hit/miss, events = saves/invalidations) +echo "=== Cache Log Tree ===" . PHP_EOL; +echo (new TreeRenderer())->render($log->toArray(), new RenderConfig(true, 0.0, 1000, true)) . PHP_EOL; + +// Machine-readable JSON conforming to the published schemas (validated below +// against the local schema files; also: `vendor/bin/stree `) +echo PHP_EOL . "=== Cache Log JSON ===" . PHP_EOL; +echo json_encode($log, JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES) . PHP_EOL; + +// The demo verifies itself: the flushed log must validate offline against +// docs/schemas/context (exits non-zero on any violation) +validateLog($log); diff --git a/demo/run-donut.php b/demo/run-donut.php index 52f17609..49aec203 100644 --- a/demo/run-donut.php +++ b/demo/run-donut.php @@ -18,15 +18,18 @@ use BEAR\QueryRepository\FakeEtagPoolModule; use BEAR\QueryRepository\ModuleFactory; use BEAR\QueryRepository\QueryRepositoryInterface; -use BEAR\QueryRepository\RepositoryLoggerInterface; use BEAR\QueryRepository\ResourceStorageInterface; use BEAR\QueryRepository\UriTag; use BEAR\Resource\ResourceInterface; use BEAR\Resource\Uri; +use Koriym\SemanticLogger\SemanticLoggerInterface; +use Koriym\SemanticLogger\Stree\RenderConfig; +use Koriym\SemanticLogger\Stree\TreeRenderer; use Madapaja\TwigModule\TwigModule; use Ray\Di\Injector; require dirname(__DIR__) . '/vendor/autoload.php'; +require __DIR__ . '/validate.php'; // Scenario descriptions (for humans) echo <<<'SCENARIOS' @@ -62,21 +65,25 @@ $resource = $injector->getInstance(ResourceInterface::class); $repository = $injector->getInstance(QueryRepositoryInterface::class); $storage = $injector->getInstance(ResourceStorageInterface::class); -$logger = $injector->getInstance(RepositoryLoggerInterface::class); +$logger = $injector->getInstance(SemanticLoggerInterface::class); -// Execute scenarios silently -$logger->log('request-start', ['uri' => 'page://self/html/blog-posting']); -$resource->get('page://self/html/blog-posting'); // 1. Initial access +// Execute scenarios. The donut GET scope wraps the embedded comment fetch. +$resource->get('page://self/html/blog-posting'); // 1. Initial access +$resource->get('page://self/html/blog-posting'); // 2. Re-access (cache-hit) +$repository->purge(new Uri('page://self/html/comment')); // 3. Manual purge of comment (top-level) +$resource->get('page://self/html/blog-posting'); // 4. Access after invalidation -$logger->log('request-start', ['uri' => 'page://self/html/blog-posting']); -$resource->get('page://self/html/blog-posting'); // 2. Re-access (cache-hit) +$log = $logger->flush(); -$logger->log('request-start', ['uri' => 'page://self/html/comment', 'method' => 'invalidate']); -$storage->invalidateTags([(new UriTag())(new Uri('page://self/html/comment'))]); // 3. Invalidate comment +// Human/AI-readable tree (open = embed scope, close = hit/miss, events = saves/invalidations) +echo "=== Cache Log Tree ===" . PHP_EOL; +echo (new TreeRenderer())->render($log->toArray(), new RenderConfig(true, 0.0, 1000, true)) . PHP_EOL; -$logger->log('request-start', ['uri' => 'page://self/html/blog-posting']); -$resource->get('page://self/html/blog-posting'); // 4. Access after invalidation +// Machine-readable JSON conforming to the published schemas (validated below +// against the local schema files; also: `vendor/bin/stree `) +echo PHP_EOL . "=== Cache Log JSON ===" . PHP_EOL; +echo json_encode($log, JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES) . PHP_EOL; -// Output logs only -echo "=== Cache Log ===" . PHP_EOL; -echo $logger . PHP_EOL; +// The demo verifies itself: the flushed log must validate offline against +// docs/schemas/context (exits non-zero on any violation) +validateLog($log); diff --git a/demo/run.php b/demo/run.php index 74245ac6..c4c97c1f 100644 --- a/demo/run.php +++ b/demo/run.php @@ -4,6 +4,9 @@ use BEAR\Resource\ResourceInterface; use FakeVendor\DemoApp\AppModule; +use Koriym\SemanticLogger\SemanticLoggerInterface; +use Koriym\SemanticLogger\Stree\RenderConfig; +use Koriym\SemanticLogger\Stree\TreeRenderer; use Ray\Di\Injector; function echoRo(BEAR\Resource\ResourceObject $ro) @@ -19,9 +22,11 @@ function echoRo(BEAR\Resource\ResourceObject $ro) /* @var $loader \Composer\Autoload\ClassLoader */ $loader = require \dirname(__DIR__) . '/vendor/autoload.php'; $loader->addPsr4('FakeVendor\DemoApp\\', __DIR__); +require __DIR__ . '/validate.php'; +$injector = new Injector(new AppModule, __DIR__ . '/tmp'); /* @var $resource ResourceInterface */ -$resource = (new Injector(new AppModule, __DIR__ . '/tmp'))->getInstance(ResourceInterface::class); +$resource = $injector->getInstance(ResourceInterface::class); echoRo($resource->uri('app://self/user')(['id' => 1])); // create cache @@ -32,3 +37,17 @@ function echoRo(BEAR\Resource\ResourceObject $ro) echoRo($resource->uri('app://self/user')(['id' => 1])); // return cache echoRo($resource->uri('app://self/user')(['id' => 1])); // return cache + +// The semantic cache log of the session above: an open/event/close tree +// (GET scopes, the onPatch command scope, saves and hits) plus the +// schema-conforming JSON. This is the machine-verifiable view of the +// TTL-less, event-driven cache the HTTP output only hints at via Age. +$log = $injector->getInstance(SemanticLoggerInterface::class)->flush(); + +echo PHP_EOL . "=== Cache Log Tree ===" . PHP_EOL; +echo (new TreeRenderer())->render($log->toArray(), new RenderConfig(true, 0.0, 1000, true)) . PHP_EOL; + +echo PHP_EOL . "=== Cache Log JSON ===" . PHP_EOL; +echo json_encode($log, JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES) . PHP_EOL; + +validateLog($log); diff --git a/demo/validate.php b/demo/validate.php new file mode 100644 index 00000000..75cccc39 --- /dev/null +++ b/demo/validate.php @@ -0,0 +1,73 @@ +toArray(); + $file = (string) tempnam(sys_get_temp_dir(), 'slog'); + file_put_contents($file, (string) json_encode($tree, JSON_UNESCAPED_SLASHES)); + + $exception = null; + ob_start(); + try { + (new SemanticLogValidator())->validate($file, dirname(__DIR__) . '/docs/schemas/context'); + } catch (RuntimeException $e) { + $exception = $e; + } finally { + $details = (string) ob_get_clean(); + unlink($file); + } + + if ($exception !== null) { + echo $details; // the validator's per-violation report + echo 'Schema validation: FAILED (' . $exception->getMessage() . ')' . PHP_EOL; + exit(1); + } + + echo sprintf('Schema validation: OK (%d entries)', countLogEntries($tree)) . PHP_EOL; +} + +/** + * Count every entry in the log tree: open scopes, their closes and events, recursively + * + * @param array $node + */ +function countLogEntries(array $node): int +{ + $count = 0; + $opens = $node['open'] ?? []; + if (is_array($opens)) { + foreach ($opens as $child) { + if (! is_array($child)) { + continue; + } + + $count += 1 + countLogEntries($child); // the scope itself + its contents + $count += isset($child['close']) ? 1 : 0; + } + } + + $events = $node['events'] ?? []; + + return $count + (is_array($events) ? count($events) : 0); +} diff --git a/docs/llms-full.txt b/docs/llms-full.txt index 955bb609..8a8aaba8 100644 --- a/docs/llms-full.txt +++ b/docs/llms-full.txt @@ -173,52 +173,39 @@ class BlogPage extends ResourceObject } ``` -## Repository Logger +## Cache Log (Semantic Log) -Cache operations are logged in JSON format for debugging and monitoring. +Cache operations are logged as an open/event/close tree (Koriym.SemanticLogger) whose nesting **is** the embed/dependency structure: a parent's embedded child GETs appear as nested scopes, no reconstruction needed. Every entry carries a typed context object and a `schemaUrl` pointing at its per-context JSON Schema, so the log is self-describing. -```json -{"op":"save-value","uri":"page://self/user","tags":["etag123","_user_"],"ttl":3600} -{"op":"invalidate-etag","tags":["_user_"]} -{"op":"put-query-repository","uri":"app://self/posts"} -{"op":"cache-hit","uri":"page://self/user"} -{"op":"cache-miss","uri":"page://self/user"} -{"op":"depends-on","parent":"page://self/blog","child":"app://self/comment","childTags":["_comment_id=1"]} -``` - -### Log Operations - -| Operation | Description | -|-----------|-------------| -| `request-start` | Request boundary marker (uri, optional method) | -| `cache-hit` | Cached resource returned without method execution | -| `cache-miss` | Cache not found, method executed | -| `save-value` | Resource body cached | -| `save-view` | Resource body + rendered view cached | -| `save-etag` | ETag stored for validation | -| `depends-on` | Parent resource registered dependency on child via tags | -| `invalidate-etag` | Cache invalidated by tags | -| `purge-query-repository` | Cache purge initiated | -| `put-query-repository` | Cache store initiated | +### Log Contexts -#### Donut Cache Operations +| Context (type) | Kind | Description | +|----------------|------|-------------| +| `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`) | +| `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 | +| `save_value` / `save_view` / `save_etag` / `save_donut` / `save_donut_view` | event | What was stored, with `tags`, `ttl` (seconds until expiry; 0/null = no expiry set), and the `saved` outcome | +| `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 decided by same-scope tag correlation — see below | +| `purge` | event | An explicit purge request | +| `put_skipped` (`uri`/`reason`[/`code`]) | event | A miss was not followed by a put (`reason`: `etag-present` / `error-code` with the actual response `code` / `not-cacheable`) | +| `cache_error` (`uri`/`operation`/`error`) | event | The cache layer itself threw (e.g. cache server down); `operation`: `read` / `write` | +| `put_donut` / `refresh_donut` | event | Donut store / re-render from a template hit | +| `log_session_broken` (`reason`) | open/close | Sentinel: the previous logging session was broken and its records discarded; the flush containing it holds ONLY this scope — that window's cache activity is unknown, not absent | +| `manual_store` / `manual_purge` / `manual_invalidate` (+ `*_result` closes) | open | Scope rooting a top-level (non-AOP) put/purge/invalidate | -| Operation | Description | -|-----------|-------------| -| `try-donut-view` | Attempt to retrieve complete rendered view | -| `found-donut-view` | Complete view found in cache | -| `try-donut` | Attempt to retrieve donut structure | -| `no-donut-found` | Donut structure not in cache | -| `put-donut` | Store donut structure | -| `save-donut` | Save donut structure to cache | -| `save-donut-view` | Save complete rendered view | -| `refresh-donut` | Reuse donut structure, regenerate inner content | +An ETag with an 'r' suffix (e.g., "123456r") marks a refreshed donut: the outer shell was reused while the inner dynamic content was regenerated. -The `depends-on` log is useful for understanding cache invalidation chains - when a child is purged, all parents with matching tags are automatically invalidated. +### Verifying the event-driven cache from logs -The `refresh-donut` indicates the donut (outer shell) was reused while the hole (inner dynamic content) was regenerated. ETag with 'r' suffix (e.g., "123456r") indicates a refreshed donut. +- Event-driven entries appear with their configured TTL in seconds (`ttl` = 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. +- 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 (direct put/purge/invalidate calls). +- 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 when, scanning forward from it within the SAME scope's event stream, the first `save_*` whose `tags` include its tags is reached with only `depends_on` events for the same resource in between — regardless of the enclosing scope type (`get` or `command`). If another `invalidate`/`purge` intervenes first, it is a real invalidation (a `#[Refresh]` command shows both shapes: the purge's invalidate is real, the re-put's deleteEtag is cleanup). In donut scopes match against `save_etag`/`save_donut_view` (`save_donut`'s tags may exclude the URI tag — a known ordering limitation); if neither is present (a donut declaring no Surrogate-Key), classification is undecidable from the log alone — this overrides the rule above: do not conclude a real invalidation merely from the absence of a matching `save_*`. 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. +- Check outcome fields: `saved: false` on a save context means the pool rejected the entry — it is NOT cached despite the save event. `cdn` on `invalidate` is tri-state: `purged` (a configured purger ran), `failed` (the purge threw; fail-closed, after local pools were invalidated), `skipped` (NullPurger, no CDN configured). A `cache_error` event (`operation`: `read`/`write`) means the cache layer itself is degraded; a `cache_miss` after it is not a cold cache. A `log_session_broken` scope means the previous logging session was discarded — that window's cache activity is unknown, not absent. +- Events within one scope are time-ordered; the relative ordering BETWEEN a scope's events and a nested scope's contents is not represented in the tree JSON (open children and events are separate arrays, no shared sequence). To determine final state after competing save/invalidate, use scope nesting plus the next GET's hit/miss as ground truth. (A per-entry sequence is being proposed upstream to Koriym.SemanticLogger.) -Schema: docs/schemas/repository-log.json +Schemas: docs/schemas/context/ (one JSON Schema per context, e.g. docs/schemas/context/save_value.json; each log entry links its own via `schemaUrl`) ## Architecture @@ -246,4 +233,4 @@ Schema: docs/schemas/repository-log.json ## Schemas -- Repository Log Format: https://bearsunday.github.io/BEAR.QueryRepository/schemas/repository-log.json +- Cache log context schemas: https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/ (one JSON Schema per context, e.g. https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/save_value.json) diff --git a/docs/llms.txt b/docs/llms.txt index ae0d9a0a..15234abf 100644 --- a/docs/llms.txt +++ b/docs/llms.txt @@ -32,6 +32,22 @@ class User extends ResourceObject - Manual: https://bearsunday.github.io/manuals/1.0/en/cache.html - Repository: https://github.com/bearsunday/BEAR.QueryRepository +## Cache Log (Semantic Log) + +Cache operations are logged as an open/event/close tree (Koriym.SemanticLogger) whose nesting **is** the embed/dependency structure. Every entry carries a typed context and a `schemaUrl` pointing at its per-context JSON Schema, so the log is self-describing. + +- A resource GET opens a `get` scope; embedded child GETs nest under it; the scope closes with `cache_hit` / `cache_miss` (field `layer`: `resource` / `donut` / `donut-view`). +- Saves (`save_value`, `save_view`, `save_etag`, `save_donut`, `save_donut_view`), dependencies (`depends_on`) and invalidations (`invalidate`) are events inside the active scope. A write opens a `command` scope recording the method, its `#[Refresh]`/`#[Purge]` annotations and the producing interceptor (`source`). + +Verifying the event-driven cache from logs: + +- Event-driven entries appear with their configured TTL in seconds (`ttl` = 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. +- 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 (direct put/purge/invalidate calls). +- 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 when, scanning forward from it within the SAME scope's event stream, the first `save_*` whose `tags` include its tags is reached with only `depends_on` events for the same resource in between — regardless of the enclosing scope type (`get` or `command`). If another `invalidate`/`purge` intervenes first, it is a real invalidation (a `#[Refresh]` command shows both shapes: the purge's invalidate is real, the re-put's deleteEtag is cleanup). In donut scopes match against `save_etag`/`save_donut_view` (`save_donut`'s tags may exclude the URI tag — a known ordering limitation); if neither is present (a donut declaring no Surrogate-Key), classification is undecidable from the log alone — this overrides the rule above: do not conclude a real invalidation merely from the absence of a matching `save_*`. 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. +- Check outcome fields: `saved: false` on a save context means the pool rejected the entry (it is NOT cached); `cdn` on `invalidate` is tri-state — `purged` (a configured purger ran), `failed` (the purge threw; fail-closed, after local pools were invalidated), `skipped` (NullPurger, no CDN configured). A `cache_error` event (`operation`: `read`/`write`) means the cache layer itself is degraded — a `cache_miss` after it is not a cold cache. A `log_session_broken` scope means the previous logging session was discarded — that window's cache activity is unknown, not absent. +- Events within one scope are time-ordered; the relative ordering BETWEEN a scope's events and a nested scope's contents is not represented in the tree JSON (open children and events are separate arrays, no shared sequence). To determine final state after competing save/invalidate, use scope nesting plus the next GET's hit/miss as ground truth. (A per-entry sequence is being proposed upstream to Koriym.SemanticLogger.) + ## Schemas -- Repository Log Format: https://bearsunday.github.io/BEAR.QueryRepository/schemas/repository-log.json +- Cache log context schemas: https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/ (one JSON Schema per context, e.g. https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/save_value.json) diff --git a/docs/schemas/context/cache_error.json b/docs/schemas/context/cache_error.json new file mode 100644 index 00000000..35a3bdbb --- /dev/null +++ b/docs/schemas/context/cache_error.json @@ -0,0 +1,27 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/cache_error.json", + "title": "cache_error", + "description": "Event: the cache layer itself errored (e.g. cache server down). A cache_miss after this event means the entry could not be read, not that it was never cached.", + "type": "object", + "required": [ + "uri", + "operation", + "error" + ], + "properties": { + "uri": { + "type": "string" + }, + "operation": { + "description": "which side of the cache failed: read (the repository get/getDonut call) or write (the put/purge call)", + "type": "string", + "enum": ["read", "write"] + }, + "error": { + "description": "The throwable message from the failed cache operation", + "type": "string" + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/cache_hit.json b/docs/schemas/context/cache_hit.json new file mode 100644 index 00000000..e6300409 --- /dev/null +++ b/docs/schemas/context/cache_hit.json @@ -0,0 +1,21 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/cache_hit.json", + "title": "cache_hit", + "description": "Close/event: a cache lookup hit at the given layer. As a scope close it reports only the final layer's outcome; sibling events in the same scope may show the entry was rebuilt (e.g. refresh_donut) or that a content-layer miss occurred, so a hit close does not by itself prove the whole subtree was served unchanged.", + "type": "object", + "required": [ + "layer" + ], + "properties": { + "layer": { + "type": "string", + "enum": [ + "resource", + "donut", + "donut-view" + ] + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/cache_miss.json b/docs/schemas/context/cache_miss.json new file mode 100644 index 00000000..016f6204 --- /dev/null +++ b/docs/schemas/context/cache_miss.json @@ -0,0 +1,21 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/cache_miss.json", + "title": "cache_miss", + "description": "Close/event: a cache lookup miss at the given layer.", + "type": "object", + "required": [ + "layer" + ], + "properties": { + "layer": { + "type": "string", + "enum": [ + "resource", + "donut", + "donut-view" + ] + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/command.json b/docs/schemas/context/command.json new file mode 100644 index 00000000..ff8b98c1 --- /dev/null +++ b/docs/schemas/context/command.json @@ -0,0 +1,42 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/command.json", + "title": "command", + "description": "Open: a write/command scope (#[Refresh]/#[Purge]); purges nest under it.", + "type": "object", + "required": [ + "method", + "annotations", + "source" + ], + "properties": { + "method": { + "type": "string" + }, + "annotations": { + "description": "the #[Refresh]/#[Purge] annotations on the command method; empty on the CacheableResponse (donut-command) path by design — that path refreshes by resource identity, not by annotation", + "type": "array", + "items": { + "type": "object", + "required": [ + "class", + "uri" + ], + "properties": { + "class": { + "type": "string" + }, + "uri": { + "type": "string" + } + }, + "additionalProperties": false + } + }, + "source": { + "description": "class basename of the producing interceptor; built-in producers are CommandInterceptor, DonutCommandInterceptor and RefreshInterceptor, but any custom command interceptor may appear here", + "type": "string" + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/command_result.json b/docs/schemas/context/command_result.json new file mode 100644 index 00000000..be1b0c17 --- /dev/null +++ b/docs/schemas/context/command_result.json @@ -0,0 +1,18 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/command_result.json", + "title": "command_result", + "description": "Close of a command scope: the resulting HTTP status code.", + "type": "object", + "required": [ + "code" + ], + "properties": { + "code": { + "type": "integer", + "minimum": 100, + "maximum": 599 + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/depends_on.json b/docs/schemas/context/depends_on.json new file mode 100644 index 00000000..78ccaa76 --- /dev/null +++ b/docs/schemas/context/depends_on.json @@ -0,0 +1,27 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/depends_on.json", + "title": "depends_on", + "description": "Event: a parent now depends on a child (dependency-graph edge).", + "type": "object", + "required": [ + "parent", + "child", + "childTags" + ], + "properties": { + "parent": { + "type": "string" + }, + "child": { + "type": "string" + }, + "childTags": { + "type": "array", + "items": { + "type": "string" + } + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/get.json b/docs/schemas/context/get.json new file mode 100644 index 00000000..af1511f6 --- /dev/null +++ b/docs/schemas/context/get.json @@ -0,0 +1,16 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/get.json", + "title": "get", + "description": "Open: a resource (or donut) GET scope; embedded child GETs nest under it.", + "type": "object", + "required": [ + "uri" + ], + "properties": { + "uri": { + "type": "string" + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/invalidate.json b/docs/schemas/context/invalidate.json new file mode 100644 index 00000000..19b5588e --- /dev/null +++ b/docs/schemas/context/invalidate.json @@ -0,0 +1,53 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/invalidate.json", + "title": "invalidate", + "description": "Event: tag invalidation outcome across the local pools and the CDN purger (cdn: \"purged\" = a real purger ran without error; \"failed\" = the purge threw; \"skipped\" = the bound purger is NullPurger, no CDN configured). Pre-write cleanup vs real invalidation is decided by tag correlation, not by scope type: scanning forward from an invalidate within the SAME scope's event stream, it is pre-write cleanup iff the first save_* event whose tags include the invalidate's tags is reached with only depends_on events for the same resource in between — regardless of the enclosing scope type (get or command). If another invalidate or purge intervenes before a matching save_*, it is a real invalidation (a #[Refresh] command shows both shapes: the purge's invalidate is real, the re-put's own deleteEtag is cleanup). In donut scopes match against save_etag/save_donut_view — save_donut's tags may exclude the URI tag (known ordering limitation); when neither save_etag nor save_donut_view is present in the scope (a donut resource declaring no Surrogate-Key), the classification is undecidable from the log alone — this overrides the rule above: do not conclude a real invalidation merely from the absence of a matching save_*. Note the pre-write invalidate uses the resource's own URI tag, which is also its parents' surrogate key, so a child refill visibly purges the parent entry — visible by design.", + "type": "object", + "required": [ + "tags", + "roPool", + "etagPool", + "cdn", + "durationMs" + ], + "properties": { + "tags": { + "type": "array", + "items": { + "type": "string" + } + }, + "roPool": { + "description": "Outcome of invalidating the tags in the Resource Object pool", + "type": "string", + "enum": [ + "invalidated", + "failed" + ] + }, + "etagPool": { + "description": "Outcome of invalidating the tags in the ETag pool", + "type": "string", + "enum": [ + "invalidated", + "failed" + ] + }, + "cdn": { + "description": "Outcome of the CDN surrogate-key purge: \"purged\" = a configured purger ran without error; \"failed\" = the purge threw (fail-closed: the exception surfaces after the local pools were invalidated, so a \"failed\" outcome always accompanies a thrown exception); \"skipped\" = the bound purger is NullPurger, i.e. no CDN is configured and nothing was purged by design", + "type": "string", + "enum": [ + "purged", + "failed", + "skipped" + ] + }, + "durationMs": { + "description": "Wall-clock duration of the invalidation in milliseconds", + "type": "number", + "minimum": 0 + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/log_session_broken.json b/docs/schemas/context/log_session_broken.json new file mode 100644 index 00000000..0bf5a69f --- /dev/null +++ b/docs/schemas/context/log_session_broken.json @@ -0,0 +1,17 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/log_session_broken.json", + "title": "log_session_broken", + "description": "Open/close sentinel: the previous logging session was broken (e.g. a LIFO open/close violation or an unclosed session) and its records were discarded at flush. A flush containing this scope contains ONLY it — the wiped session's entries are gone, so the cache activity of that window is unknown, not \"no cache activity\". The next session logs normally.", + "type": "object", + "required": [ + "reason" + ], + "properties": { + "reason": { + "description": "The throwable message (or class) that broke the session", + "type": "string" + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/manual_invalidate.json b/docs/schemas/context/manual_invalidate.json new file mode 100644 index 00000000..5762bc68 --- /dev/null +++ b/docs/schemas/context/manual_invalidate.json @@ -0,0 +1,15 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/manual_invalidate.json", + "title": "manual_invalidate", + "description": "Open: an application-initiated (manual) tag invalidation.", + "type": "object", + "required": ["tags"], + "properties": { + "tags": { + "type": "array", + "items": { "type": "string" } + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/manual_purge.json b/docs/schemas/context/manual_purge.json new file mode 100644 index 00000000..aba1f596 --- /dev/null +++ b/docs/schemas/context/manual_purge.json @@ -0,0 +1,12 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/manual_purge.json", + "title": "manual_purge", + "description": "Open: an application-initiated (manual) purge of a URI.", + "type": "object", + "required": ["uri"], + "properties": { + "uri": { "type": "string" } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/manual_purge_result.json b/docs/schemas/context/manual_purge_result.json new file mode 100644 index 00000000..b4af1d91 --- /dev/null +++ b/docs/schemas/context/manual_purge_result.json @@ -0,0 +1,12 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/manual_purge_result.json", + "title": "manual_purge_result", + "description": "Close of a manual_purge scope: outcome of the local-pool invalidation.", + "type": "object", + "required": ["result"], + "properties": { + "result": { "type": "string", "enum": ["purged", "failed"] } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/manual_store.json b/docs/schemas/context/manual_store.json new file mode 100644 index 00000000..5729639a --- /dev/null +++ b/docs/schemas/context/manual_store.json @@ -0,0 +1,12 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/manual_store.json", + "title": "manual_store", + "description": "Open: an application-initiated (manual) store of a resource.", + "type": "object", + "required": ["uri"], + "properties": { + "uri": { "type": "string" } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/manual_store_result.json b/docs/schemas/context/manual_store_result.json new file mode 100644 index 00000000..e38bb79e --- /dev/null +++ b/docs/schemas/context/manual_store_result.json @@ -0,0 +1,16 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/manual_store_result.json", + "title": "manual_store_result", + "description": "Close of a manual_store scope: outcome of the resource store.", + "type": "object", + "required": ["result"], + "properties": { + "result": { + "description": "reflects the save_value/save_view outcome only; a failed save_etag inside the same scope does not flip it — inspect the nested save_etag event's \"saved\" field for that", + "type": "string", + "enum": ["stored", "failed"] + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/purge.json b/docs/schemas/context/purge.json new file mode 100644 index 00000000..9abb6105 --- /dev/null +++ b/docs/schemas/context/purge.json @@ -0,0 +1,16 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/purge.json", + "title": "purge", + "description": "Event: an explicit purge of a URI was requested.", + "type": "object", + "required": [ + "uri" + ], + "properties": { + "uri": { + "type": "string" + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/put_donut.json b/docs/schemas/context/put_donut.json new file mode 100644 index 00000000..3732f3a7 --- /dev/null +++ b/docs/schemas/context/put_donut.json @@ -0,0 +1,34 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/put_donut.json", + "title": "put_donut", + "description": "Event: a donut was put with its TTLs.", + "type": "object", + "required": [ + "uri", + "ttl", + "sMaxAge" + ], + "properties": { + "uri": { + "type": "string" + }, + "ttl": { + "description": "seconds until expiry of the donut template entry (putStatic: the $ttl argument; putDonut: $donutTtl). Interceptor-driven puts log null (no explicit TTL).", + "type": [ + "integer", + "null" + ], + "minimum": 0 + }, + "sMaxAge": { + "description": "CDN s-maxage in seconds (putStatic only: also used as the rendered view's TTL; putDonut and interceptor-driven puts log null)", + "type": [ + "integer", + "null" + ], + "minimum": 0 + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/put_skipped.json b/docs/schemas/context/put_skipped.json new file mode 100644 index 00000000..b76944bf --- /dev/null +++ b/docs/schemas/context/put_skipped.json @@ -0,0 +1,28 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/put_skipped.json", + "title": "put_skipped", + "description": "Event: a miss was not followed by a put. Records the fact that no store happened and why (reason); whether skipping the put is correct is for the reader to judge from the recorded reason and code.", + "type": "object", + "required": [ + "uri", + "reason" + ], + "properties": { + "uri": { + "type": "string" + }, + "reason": { + "description": "why no store happened: the response already carries an ETag (etag-present), is an error response (error-code), or the entry kind is not whole-content cacheable (not-cacheable: a donut page served from its template plus inner caches is never stored as a rendered page)", + "type": "string", + "enum": ["etag-present", "error-code", "not-cacheable"] + }, + "code": { + "description": "the response status code when reason is error-code; null otherwise", + "type": ["integer", "null"], + "minimum": 100, + "maximum": 599 + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/refresh_donut.json b/docs/schemas/context/refresh_donut.json new file mode 100644 index 00000000..ae81cd10 --- /dev/null +++ b/docs/schemas/context/refresh_donut.json @@ -0,0 +1,16 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/refresh_donut.json", + "title": "refresh_donut", + "description": "Event: a donut page was re-rendered after the donut TEMPLATE lookup hit. The cached template is reused; what is rebuilt is the rendered view — each embedded placeholder is re-fetched (refreshing that inner resource's own cache entry) and the template is re-rendered. It marks a partial rebuild, not a full miss.", + "type": "object", + "required": [ + "uri" + ], + "properties": { + "uri": { + "type": "string" + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/save_donut.json b/docs/schemas/context/save_donut.json new file mode 100644 index 00000000..8d2426ba --- /dev/null +++ b/docs/schemas/context/save_donut.json @@ -0,0 +1,38 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/save_donut.json", + "title": "save_donut", + "description": "Event: a donut structure (template) was stored.", + "type": "object", + "required": [ + "uri", + "tags", + "ttl", + "saved" + ], + "properties": { + "uri": { + "type": "string" + }, + "tags": { + "description": "invalidation tags registered with the entry (the Surrogate-Key header keys captured at put time; unlike the other save_* events this is not guaranteed to include the resource's own URI tag)", + "type": "array", + "items": { + "type": "string" + } + }, + "ttl": { + "description": "seconds until expiry of the donut template entry; 0 or null means no expiry is set (the entry lives until event-driven invalidation); 31536000 is the `never` expiry convention (365 days), an effectively-unbounded placeholder — event-driven invalidation is the intended eviction path", + "type": [ + "integer", + "null" + ], + "minimum": 0 + }, + "saved": { + "type": "boolean", + "description": "Whether the cache pool accepted the entry. false means the store failed silently (e.g. pool error) — the entry is NOT cached despite this event." + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/save_donut_view.json b/docs/schemas/context/save_donut_view.json new file mode 100644 index 00000000..4a9230c8 --- /dev/null +++ b/docs/schemas/context/save_donut_view.json @@ -0,0 +1,38 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/save_donut_view.json", + "title": "save_donut_view", + "description": "Event: a rendered donut view was stored.", + "type": "object", + "required": [ + "uri", + "tags", + "ttl", + "saved" + ], + "properties": { + "uri": { + "type": "string" + }, + "tags": { + "description": "invalidation tags registered with the entry, including the resource's own URI tag", + "type": "array", + "items": { + "type": "string" + } + }, + "ttl": { + "description": "seconds until expiry of the rendered view entry; 0 or null means no expiry is set (the entry lives until event-driven invalidation); 31536000 is the `never` expiry convention (365 days), an effectively-unbounded placeholder — event-driven invalidation is the intended eviction path", + "type": [ + "integer", + "null" + ], + "minimum": 0 + }, + "saved": { + "type": "boolean", + "description": "Whether the cache pool accepted the entry. false means the store failed silently (e.g. pool error) — the entry is NOT cached despite this event." + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/save_etag.json b/docs/schemas/context/save_etag.json new file mode 100644 index 00000000..043b1772 --- /dev/null +++ b/docs/schemas/context/save_etag.json @@ -0,0 +1,42 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/save_etag.json", + "title": "save_etag", + "description": "Event: an ETag entry was stored with its invalidation tags.", + "type": "object", + "required": [ + "uri", + "etag", + "tags", + "ttl", + "saved" + ], + "properties": { + "uri": { + "type": "string" + }, + "etag": { + "type": "string" + }, + "tags": { + "description": "invalidation tags registered with the entry, including the resource's own URI tag", + "type": "array", + "items": { + "type": "string" + } + }, + "ttl": { + "description": "seconds until expiry; 0 or null means no expiry is set; 31536000 is the `never` expiry convention (365 days), an effectively-unbounded placeholder — event-driven invalidation is the intended eviction path", + "type": [ + "integer", + "null" + ], + "minimum": 0 + }, + "saved": { + "type": "boolean", + "description": "Whether the cache pool accepted the entry. false means the store failed silently (e.g. pool error) — the entry is NOT cached despite this event." + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/save_value.json b/docs/schemas/context/save_value.json new file mode 100644 index 00000000..518d437f --- /dev/null +++ b/docs/schemas/context/save_value.json @@ -0,0 +1,38 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/save_value.json", + "title": "save_value", + "description": "Event: a resource value (body) was stored.", + "type": "object", + "required": [ + "uri", + "tags", + "ttl", + "saved" + ], + "properties": { + "uri": { + "type": "string" + }, + "tags": { + "description": "invalidation tags registered with the entry, including the resource's own URI tag", + "type": "array", + "items": { + "type": "string" + } + }, + "ttl": { + "description": "seconds until expiry; 0 or null means no expiry is set (the entry lives until event-driven invalidation); 31536000 is the `never` expiry convention (365 days), an effectively-unbounded placeholder — event-driven invalidation is the intended eviction path", + "type": [ + "integer", + "null" + ], + "minimum": 0 + }, + "saved": { + "type": "boolean", + "description": "Whether the cache pool accepted the entry. false means the store failed silently (e.g. pool error) — the entry is NOT cached despite this event." + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/save_view.json b/docs/schemas/context/save_view.json new file mode 100644 index 00000000..b8ff41a3 --- /dev/null +++ b/docs/schemas/context/save_view.json @@ -0,0 +1,38 @@ +{ + "$schema": "https://json-schema.org/draft/2020-12/schema", + "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/save_view.json", + "title": "save_view", + "description": "Event: a rendered resource view was stored.", + "type": "object", + "required": [ + "uri", + "tags", + "ttl", + "saved" + ], + "properties": { + "uri": { + "type": "string" + }, + "tags": { + "description": "invalidation tags registered with the entry, including the resource's own URI tag", + "type": "array", + "items": { + "type": "string" + } + }, + "ttl": { + "description": "seconds until expiry; 0 or null means no expiry is set (the entry lives until event-driven invalidation); 31536000 is the `never` expiry convention (365 days), an effectively-unbounded placeholder — event-driven invalidation is the intended eviction path", + "type": [ + "integer", + "null" + ], + "minimum": 0 + }, + "saved": { + "type": "boolean", + "description": "Whether the cache pool accepted the entry. false means the store failed silently (e.g. pool error) — the entry is NOT cached despite this event." + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/repository-log.json b/docs/schemas/repository-log.json deleted file mode 100644 index 1c2a6392..00000000 --- a/docs/schemas/repository-log.json +++ /dev/null @@ -1,226 +0,0 @@ -{ - "$schema": "https://json-schema.org/draft/2020-12/schema", - "$id": "https://bearsunday.github.io/BEAR.QueryRepository/schemas/repository-log.json", - "title": "BEAR.QueryRepository Log Entry", - "description": "JSON log entry format for BEAR.QueryRepository cache operations. For conceptual documentation (Donut Cache, Cache Dependencies), see: https://bearsunday.github.io/llms-full.txt and docs/llms-full.txt", - "type": "object", - "required": ["op"], - "properties": { - "op": { - "type": "string", - "description": "Operation name", - "enum": [ - "request-start", - "save-value", - "save-view", - "save-etag", - "save-donut", - "save-donut-view", - "invalidate-etag", - "put-query-repository", - "purge-query-repository", - "put-donut", - "try-donut-view", - "found-donut-view", - "try-donut", - "no-donut-found", - "refresh-donut", - "cache-hit", - "cache-miss", - "depends-on" - ] - }, - "uri": { - "type": "string", - "description": "Resource URI (e.g., page://self/user, app://self/posts)", - "pattern": "^(page|app)://self/.+" - }, - "tags": { - "type": "array", - "description": "Cache tags for invalidation", - "items": { - "type": "string" - } - }, - "surrogateKeys": { - "type": "array", - "description": "Surrogate keys for CDN cache invalidation", - "items": { - "type": "string" - } - }, - "etag": { - "type": "string", - "description": "Entity tag for cache validation" - }, - "ttl": { - "type": ["integer", "null"], - "description": "Time to live in seconds", - "minimum": 0 - }, - "sMaxAge": { - "type": ["integer", "null"], - "description": "Shared cache max age in seconds (for CDN)", - "minimum": 0 - }, - "parent": { - "type": "string", - "description": "Parent resource URI that depends on the child", - "pattern": "^(page|app)://self/.+" - }, - "child": { - "type": "string", - "description": "Child resource URI that the parent depends on", - "pattern": "^(page|app)://self/.+" - }, - "childTags": { - "type": "array", - "description": "Tags from child resource that enable dependency invalidation", - "items": { - "type": "string" - } - }, - "method": { - "type": "string", - "description": "HTTP method or operation type (used with request-start)", - "enum": ["get", "post", "put", "patch", "delete", "purge", "invalidate"] - } - }, - "allOf": [ - { - "if": { - "properties": { "op": { "const": "save-value" } } - }, - "then": { - "required": ["uri", "tags", "ttl"] - } - }, - { - "if": { - "properties": { "op": { "const": "save-view" } } - }, - "then": { - "required": ["uri", "ttl"] - } - }, - { - "if": { - "properties": { "op": { "const": "save-etag" } } - }, - "then": { - "required": ["uri", "etag", "surrogateKeys"] - } - }, - { - "if": { - "properties": { "op": { "const": "save-donut" } } - }, - "then": { - "required": ["uri", "sMaxAge"] - } - }, - { - "if": { - "properties": { "op": { "const": "save-donut-view" } } - }, - "then": { - "required": ["uri", "surrogateKeys", "sMaxAge"] - } - }, - { - "if": { - "properties": { "op": { "const": "invalidate-etag" } } - }, - "then": { - "required": ["tags"] - } - }, - { - "if": { - "properties": { "op": { "const": "put-donut" } } - }, - "then": { - "required": ["uri", "ttl"] - } - }, - { - "if": { - "properties": { "op": { "const": "cache-hit" } } - }, - "then": { - "required": ["uri"] - } - }, - { - "if": { - "properties": { "op": { "const": "cache-miss" } } - }, - "then": { - "required": ["uri"] - } - }, - { - "if": { - "properties": { "op": { "const": "depends-on" } } - }, - "then": { - "required": ["parent", "child", "childTags"] - } - } - ], - "examples": [ - { - "op": "request-start", - "uri": "page://self/user" - }, - { - "op": "request-start", - "uri": "page://self/user", - "method": "purge" - }, - { - "op": "save-value", - "uri": "page://self/user", - "tags": ["etag123", "_user_"], - "ttl": 3600 - }, - { - "op": "save-etag", - "uri": "page://self/user", - "etag": "etag123", - "surrogateKeys": ["_user_", "user-tag"] - }, - { - "op": "invalidate-etag", - "tags": ["_user_"] - }, - { - "op": "put-query-repository", - "uri": "app://self/posts" - }, - { - "op": "try-donut-view", - "uri": "page://self/blog" - }, - { - "op": "put-donut", - "uri": "page://self/blog", - "ttl": 600, - "sMaxAge": 3600 - }, - { - "op": "cache-hit", - "uri": "page://self/user" - }, - { - "op": "cache-miss", - "uri": "page://self/user" - }, - { - "op": "depends-on", - "parent": "page://self/blog", - "child": "app://self/comment", - "childTags": ["_comment_id=1"] - } - ] -} diff --git a/psalm.xml b/psalm.xml index e8b36f1e..ceaf7662 100644 --- a/psalm.xml +++ b/psalm.xml @@ -20,5 +20,12 @@ + + + + + + diff --git a/src/AbstractDonutCacheInterceptor.php b/src/AbstractDonutCacheInterceptor.php index ebd75701..584e5826 100644 --- a/src/AbstractDonutCacheInterceptor.php +++ b/src/AbstractDonutCacheInterceptor.php @@ -4,8 +4,15 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\Context\CacheErrorContext; +use BEAR\QueryRepository\Log\Context\CacheHitContext; +use BEAR\QueryRepository\Log\Context\CacheMissContext; +use BEAR\QueryRepository\Log\Context\GetContext; +use BEAR\QueryRepository\Log\Context\PutSkippedContext; +use BEAR\QueryRepository\Log\NullSemanticLogger; use BEAR\Resource\Code; use BEAR\Resource\ResourceObject; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Override; use Ray\Aop\MethodInterceptor; use Ray\Aop\MethodInvocation; @@ -23,39 +30,61 @@ abstract class AbstractDonutCacheInterceptor implements MethodInterceptor public function __construct( private readonly DonutRepositoryInterface $donutRepository, + private readonly SemanticLoggerInterface $logger = new NullSemanticLogger(), ) { } /** * {@inheritDoc} + * + * Opens a donut GET scope so embedded resources rebuilt during get()/put nest + * under this page, and the scope is closed with the donut-view hit/miss outcome. */ #[Override] final public function invoke(MethodInvocation $invocation) { $ro = $invocation->getThis(); assert($ro instanceof ResourceObject); + $openId = $this->logger->open(new GetContext((string) $ro->uri)); + $hit = false; try { - $maybeRo = $this->donutRepository->get($ro); - if ($maybeRo instanceof ResourceObject) { - return $maybeRo; + try { + $maybeRo = $this->donutRepository->get($ro); + if ($maybeRo instanceof ResourceObject) { + $hit = true; + + return $maybeRo; + } + } catch (Throwable $e) { // @codeCoverageIgnoreStart + // when cache server is down: log it so a miss here is not read as a cold cache + $this->logger->event(new CacheErrorContext((string) $ro->uri, 'read', $e->getMessage())); + $this->triggerWarning($e); + + return $invocation->proceed(); // @codeCoverageIgnoreEnd } - } catch (Throwable $e) { // @codeCoverageIgnoreStart - // when cache server is down - $this->triggerWarning($e); - return $invocation->proceed(); // @codeCoverageIgnoreEnd - } + /** @var ResourceObject $ro */ + $ro = $invocation->proceed(); + // donut created in ResourceObject + if (isset($ro->headers[Header::ETAG]) || $ro->code >= Code::BAD_REQUEST) { + // Record why this miss is not followed by a put; without it the log looks like a lost write. + $hasEtag = isset($ro->headers[Header::ETAG]); + $this->logger->event(new PutSkippedContext((string) $ro->uri, $hasEtag ? 'etag-present' : 'error-code', $hasEtag ? null : $ro->code)); - /** @var ResourceObject $ro */ - $ro = $invocation->proceed(); - // donut created in ResourceObject - if (isset($ro->headers[Header::ETAG]) || $ro->code >= Code::BAD_REQUEST) { - return $ro; - } + return $ro; + } - return static::IS_ENTIRE_CONTENT_CACHEABLE ? // phpcs:ignore - not "self" - $this->donutRepository->putStatic($ro, null, null) : - $this->donutRepository->putDonut($ro, null); + return static::IS_ENTIRE_CONTENT_CACHEABLE ? // phpcs:ignore - not "self" + $this->donutRepository->putStatic($ro, null, null) : + $this->donutRepository->putDonut($ro, null); + } finally { + // Psalm mis-tracks the $hit flag mutated inside try when read from finally. + /** @psalm-suppress RedundantCondition, TypeDoesNotContainType */ + $this->logger->close( + $hit ? new CacheHitContext('donut-view') : new CacheMissContext('donut-view'), + $openId, + ); + } } /** @codeCoverageIgnore */ diff --git a/src/CacheDependency.php b/src/CacheDependency.php index eb79aba2..211b4bfc 100644 --- a/src/CacheDependency.php +++ b/src/CacheDependency.php @@ -4,15 +4,20 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\Context\DependsOnContext; +use BEAR\QueryRepository\Log\NullSemanticLogger; use BEAR\Resource\ResourceObject; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Override; +use function explode; use function sprintf; final readonly class CacheDependency implements CacheDependencyInterface { public function __construct( private UriTagInterface $uriTag, + private SemanticLoggerInterface $logger = new NullSemanticLogger(), ) { } @@ -31,5 +36,11 @@ public function depends(ResourceObject $from, ResourceObject $to): void $from->headers[Header::SURROGATE_KEY] = isset($from->headers[Header::SURROGATE_KEY]) ? sprintf('%s %s', $from->headers[Header::SURROGATE_KEY], $childTags) : $childTags; + + $this->logger->event(new DependsOnContext( + (string) $from->uri, + (string) $to->uri, + explode(' ', $childTags), + )); } } diff --git a/src/CacheInterceptor.php b/src/CacheInterceptor.php index 0a2287e3..b6194b9a 100644 --- a/src/CacheInterceptor.php +++ b/src/CacheInterceptor.php @@ -5,7 +5,14 @@ namespace BEAR\QueryRepository; use BEAR\QueryRepository\Exception\LogicException; +use BEAR\QueryRepository\Log\Context\CacheErrorContext; +use BEAR\QueryRepository\Log\Context\CacheHitContext; +use BEAR\QueryRepository\Log\Context\CacheMissContext; +use BEAR\QueryRepository\Log\Context\GetContext; +use BEAR\QueryRepository\Log\Context\PutSkippedContext; +use BEAR\QueryRepository\Log\NullSemanticLogger; use BEAR\Resource\ResourceObject; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Override; use Ray\Aop\MethodInterceptor; use Ray\Aop\MethodInvocation; @@ -31,43 +38,71 @@ { public function __construct( private QueryRepositoryInterface $repository, + private SemanticLoggerInterface $logger = new NullSemanticLogger(), ) { } /** * {@inheritDoc} + * + * Opens a GET scope so embedded child resources fetched during put() nest + * under this resource, and the scope is closed with the hit/miss outcome. */ #[Override] public function invoke(MethodInvocation $invocation) { $ro = $invocation->getThis(); assert($ro instanceof ResourceObject); + $openId = $this->logger->open(new GetContext((string) $ro->uri)); + $hit = false; try { - $state = $this->repository->get($ro->uri); - } catch (Throwable $e) { - $this->triggerWarning($e); + try { + $state = $this->repository->get($ro->uri); + } catch (Throwable $e) { + // The cache layer itself is degraded: log it so a miss here is not read as a cold cache + $this->logger->event(new CacheErrorContext((string) $ro->uri, 'read', $e->getMessage())); + $this->triggerWarning($e); - return $invocation->proceed(); // @codeCoverageIgnore - } + return $invocation->proceed(); + } - if ($state instanceof ResourceState) { - $state->visit($ro); + if ($state instanceof ResourceState) { + $state->visit($ro); + $hit = true; - return $ro; - } + return $ro; + } - /** @psalm-suppress MixedAssignment */ - $ro = $invocation->proceed(); - assert($ro instanceof ResourceObject); - try { - $ro->code === 200 ? $this->repository->put($ro) : $this->repository->purge($ro->uri); - } catch (LogicException $e) { - throw $e; - } catch (Throwable $e) { // @codeCoverageIgnore - $this->triggerWarning($e); // @codeCoverageIgnore - } + /** @psalm-suppress MixedAssignment */ + $ro = $invocation->proceed(); + assert($ro instanceof ResourceObject); + try { + if ($ro->code !== 200) { + // Record the actual non-200 code; without it the purge below reads + // as if a 203 and a 404 were the same thing. + $this->logger->event(new PutSkippedContext((string) $ro->uri, 'error-code', $ro->code)); + $this->repository->purge($ro->uri); + + return $ro; + } + + $this->repository->put($ro); + } catch (LogicException $e) { + throw $e; + } catch (Throwable $e) { // @codeCoverageIgnore + $this->logger->event(new CacheErrorContext((string) $ro->uri, 'write', $e->getMessage())); // @codeCoverageIgnore + $this->triggerWarning($e); // @codeCoverageIgnore + } - return $ro; + return $ro; + } finally { + // Psalm mis-tracks the $hit flag mutated inside try when read from finally. + /** @psalm-suppress RedundantCondition, TypeDoesNotContainType */ + $this->logger->close( + $hit ? new CacheHitContext('resource') : new CacheMissContext('resource'), + $openId, + ); + } } /** diff --git a/src/CommandContextFactory.php b/src/CommandContextFactory.php new file mode 100644 index 00000000..bf773846 --- /dev/null +++ b/src/CommandContextFactory.php @@ -0,0 +1,39 @@ + $invocation */ + public function __invoke(MethodInvocation $invocation, string $source): CommandContext + { + $method = $invocation->getMethod(); + $annotations = []; + foreach ($method->getAnnotations() as $annotation) { + if (! $annotation instanceof AbstractCommand) { + continue; + } + + // AbstractCommand::$uri is a declared string; no cast needed. + $annotations[] = ['class' => $annotation::class, 'uri' => $annotation->uri]; + } + + return new CommandContext($method->getName(), $annotations, $source); + } +} diff --git a/src/CommandInterceptor.php b/src/CommandInterceptor.php index 03ac15ac..bc867d88 100644 --- a/src/CommandInterceptor.php +++ b/src/CommandInterceptor.php @@ -5,9 +5,12 @@ namespace BEAR\QueryRepository; use BEAR\QueryRepository\Exception\ReturnValueIsNotResourceObjectException; +use BEAR\QueryRepository\Log\Context\CommandResultContext; +use BEAR\QueryRepository\Log\NullSemanticLogger; use BEAR\RepositoryModule\Annotation\Commands; use BEAR\Resource\Code; use BEAR\Resource\ResourceObject; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Override; use Ray\Aop\MethodInterceptor; use Ray\Aop\MethodInvocation; @@ -28,11 +31,15 @@ */ final readonly class CommandInterceptor implements MethodInterceptor { + private CommandContextFactory $commandContextFactory; + /** @param CommandInterface[] $commands */ public function __construct( #[Commands] private array $commands, + private SemanticLoggerInterface $logger = new NullSemanticLogger(), ) { + $this->commandContextFactory = new CommandContextFactory(); } /** @@ -49,12 +56,18 @@ public function invoke(MethodInvocation $invocation) throw new ReturnValueIsNotResourceObjectException($invocation->getThis()::class); } - if ($ro->code >= Code::BAD_REQUEST) { - return $ro; - } - - foreach ($this->commands as $command) { - $command->command($invocation, $ro); + // Open the scope even for a failed write: a 4xx command_result with no invalidation + // events records that the purge/refresh was correctly skipped (symmetric with the + // query side, which logs purge on non-200). + $openId = $this->logger->open(($this->commandContextFactory)($invocation, 'CommandInterceptor')); + try { + if ($ro->code < Code::BAD_REQUEST) { + foreach ($this->commands as $command) { + $command->command($invocation, $ro); + } + } + } finally { + $this->logger->close(new CommandResultContext($ro->code), $openId); } return $ro; diff --git a/src/DonutCacheModule.php b/src/DonutCacheModule.php index f444856e..d72cc58f 100644 --- a/src/DonutCacheModule.php +++ b/src/DonutCacheModule.php @@ -4,9 +4,11 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\SafeSemanticLoggerProvider; use BEAR\RepositoryModule\Annotation\CacheableResponse; use BEAR\RepositoryModule\Annotation\DonutCache; use BEAR\RepositoryModule\Annotation\RefreshCache; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Override; use Ray\Di\AbstractModule; use Ray\Di\Scope; @@ -41,6 +43,12 @@ protected function configure(): void $this->bind(HeaderSetter::class); $this->bind(CdnCacheControlHeaderSetterInterface::class)->to(CdnCacheControlHeaderSetter::class); $this->bind(DonutRepositoryInterface::class)->to(DonutRepository::class)->in(Scope::SINGLETON); + // Shared semantic logging session: open() at an interceptor and event() at storage + // resolve to the same SafeSemanticLogger singleton (see SafeSemanticLoggerProvider). + $this->bind(SemanticLoggerInterface::class)->toProvider(SafeSemanticLoggerProvider::class)->in(Scope::SINGLETON); + // BC: the legacy flat logger interface is kept bound (deprecated). Internal cache code + // now logs through SemanticLoggerInterface, so this instance receives no internal events. + /** @psalm-suppress DeprecatedClass, DeprecatedInterface */ $this->bind(RepositoryLoggerInterface::class)->to(RepositoryLogger::class)->in(Scope::SINGLETON); $this->bind(PurgerInterface::class)->to(NullPurger::class); $this->bind(UriTagInterface::class)->to(UriTag::class); diff --git a/src/DonutCommandInterceptor.php b/src/DonutCommandInterceptor.php index 9dfe4b08..2fbbcf4a 100644 --- a/src/DonutCommandInterceptor.php +++ b/src/DonutCommandInterceptor.php @@ -5,9 +5,12 @@ namespace BEAR\QueryRepository; use BEAR\QueryRepository\Exception\UnmatchedQuery; +use BEAR\QueryRepository\Log\Context\CommandResultContext; +use BEAR\QueryRepository\Log\NullSemanticLogger; use BEAR\Resource\AbstractUri; use BEAR\Resource\Code; use BEAR\Resource\ResourceObject; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Ray\Aop\MethodInterceptor; use Ray\Aop\MethodInvocation; use ReflectionMethod; @@ -31,10 +34,14 @@ */ final readonly class DonutCommandInterceptor implements MethodInterceptor { + private CommandContextFactory $commandContextFactory; + public function __construct( private DonutRepositoryInterface $repository, - private MatchQueryInterface $matchQuery + private MatchQueryInterface $matchQuery, + private SemanticLoggerInterface $logger = new NullSemanticLogger() ){ + $this->commandContextFactory = new CommandContextFactory(); } #[\Override] @@ -42,11 +49,17 @@ public function invoke(MethodInvocation $invocation): ResourceObject { $ro = $invocation->proceed(); assert($ro instanceof ResourceObject); - if ($ro->code >= Code::BAD_REQUEST) { - return $ro; - } - $this->refreshDonutAndState($ro); + // Open the scope even for a failed write: a 4xx command_result with no invalidation + // events records that the donut purge/refresh was correctly skipped. + $openId = $this->logger->open(($this->commandContextFactory)($invocation, 'DonutCommandInterceptor')); + try { + if ($ro->code < Code::BAD_REQUEST) { + $this->refreshDonutAndState($ro); + } + } finally { + $this->logger->close(new CommandResultContext($ro->code), $openId); + } return $ro; } diff --git a/src/DonutRepository.php b/src/DonutRepository.php index 8135c8db..581ebae3 100644 --- a/src/DonutRepository.php +++ b/src/DonutRepository.php @@ -4,9 +4,15 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\Context\CacheHitContext; +use BEAR\QueryRepository\Log\Context\CacheMissContext; +use BEAR\QueryRepository\Log\Context\PutDonutContext; +use BEAR\QueryRepository\Log\Context\PutSkippedContext; +use BEAR\QueryRepository\Log\Context\RefreshDonutContext; use BEAR\Resource\AbstractUri; use BEAR\Resource\ResourceInterface; use BEAR\Resource\ResourceObject; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Override; use function assert; @@ -21,7 +27,7 @@ public function __construct( private ResourceStorageInterface $resourceStorage, private ResourceInterface $resource, private CdnCacheControlHeaderSetterInterface $cdnCacheControlHeaderSetter, - private RepositoryLoggerInterface $logger, + private SemanticLoggerInterface $logger, private DonutRendererInterface $renderer, ) { } @@ -30,9 +36,7 @@ public function __construct( public function get(ResourceObject $ro): ResourceObject|null { $maybeState = $this->queryRepository->get($ro->uri); - $this->logger->log('try-donut-view', ['uri' => (string) $ro->uri]); if ($maybeState instanceof ResourceState) { - $this->logger->log('found-donut-view', ['uri' => (string) $ro->uri]); $ro->headers = $maybeState->headers; $ro->view = $maybeState->view; @@ -48,7 +52,7 @@ public function get(ResourceObject $ro): ResourceObject|null #[Override] public function putStatic(ResourceObject $ro, int|null $ttl = null, int|null $sMaxAge = null): ResourceObject { - $this->logger->log('put-donut', ['uri' => (string) $ro->uri, 'ttl' => $ttl, 'sMaxAge' => $sMaxAge]); + $this->logger->event(new PutDonutContext((string) $ro->uri, $ttl, $sMaxAge)); $keys = new SurrogateKeys($ro->uri); $keys->addTag($ro); $headerKeys = $this->getHeaderKeys($ro); @@ -70,7 +74,7 @@ public function putStatic(ResourceObject $ro, int|null $ttl = null, int|null $sM #[Override] public function putDonut(ResourceObject $ro, int|null $donutTtl): ResourceObject { - $this->logger->log('put-donut', ['uri' => (string) $ro->uri, 'ttl' => $donutTtl]); + $this->logger->event(new PutDonutContext((string) $ro->uri, $donutTtl, null)); $keys = new SurrogateKeys($ro->uri); $keyArrays = $this->getHeaderKeys($ro); $donut = ResourceDonut::create($ro, $this->renderer, $keys, $donutTtl, false); @@ -105,16 +109,22 @@ public function invalidateTags(array $tags): void private function refreshDonut(ResourceObject $ro): ResourceObject|null { $donut = $this->resourceStorage->getDonut($ro->uri); - $this->logger->log('try-donut', ['uri' => (string) $ro->uri]); if (! $donut instanceof ResourceDonut) { - $this->logger->log('no-donut-found', ['uri' => (string) $ro->uri]); + $this->logger->event(new CacheMissContext('donut')); return null; } - $this->logger->log('refresh-donut', ['uri' => (string) $ro->uri]); + $this->logger->event(new CacheHitContext('donut')); + $this->logger->event(new RefreshDonutContext((string) $ro->uri)); $donut->refresh($this->resource, $ro); if (! $donut->isCacheble) { + // The donut was created by putDonut (isCacheble=false): only the template is + // cached and the page is never stored as a rendered view, so there is no + // page-level entry to save after the refresh. Record the skip — without it + // the scope shows a refresh with no saves and no reason. + $this->logger->event(new PutSkippedContext((string) $ro->uri, 'not-cacheable')); + return $ro; } diff --git a/src/Log/Context/CacheErrorContext.php b/src/Log/Context/CacheErrorContext.php new file mode 100644 index 00000000..b212ebcb --- /dev/null +++ b/src/Log/Context/CacheErrorContext.php @@ -0,0 +1,29 @@ + $annotations + * @param string $source class basename of the producing interceptor + * (CommandInterceptor / DonutCommandInterceptor / RefreshInterceptor) + */ + public function __construct( + public readonly string $method, + public readonly array $annotations, + public readonly string $source, + ) { + } +} diff --git a/src/Log/Context/CommandResultContext.php b/src/Log/Context/CommandResultContext.php new file mode 100644 index 00000000..9f7f7fb6 --- /dev/null +++ b/src/Log/Context/CommandResultContext.php @@ -0,0 +1,21 @@ + $childTags */ + public function __construct( + public readonly string $parent, + public readonly string $child, + public readonly array $childTags, + ) { + } +} diff --git a/src/Log/Context/GetContext.php b/src/Log/Context/GetContext.php new file mode 100644 index 00000000..2004d49d --- /dev/null +++ b/src/Log/Context/GetContext.php @@ -0,0 +1,21 @@ + "invalidated" | "failed" (Symfony tag invalidation marks + * the tag version stale; it does not physically delete) + * cdn -> "purged" | "failed" | "skipped" + * ("skipped" = the bound purger is NullPurger, i.e. no CDN + * is configured — nothing was purged, but nothing was + * meant to be) + */ +final class InvalidateContext extends AbstractContext implements JsonSerializable +{ + public const TYPE = 'invalidate'; + public const SCHEMA_URL = 'https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/invalidate.json'; + + /** + * @param list $tags + * @param "purged"|"failed"|"skipped" $cdnStatus + */ + public function __construct( + public readonly array $tags, + public readonly bool $roPoolInvalidated, + public readonly bool $etagPoolInvalidated, + public readonly string $cdnStatus, + public readonly float $durationMs, + ) { + } + + /** @return array */ + #[Override] + public function jsonSerialize(): array + { + return [ + 'tags' => $this->tags, + 'roPool' => $this->roPoolInvalidated ? 'invalidated' : 'failed', + 'etagPool' => $this->etagPoolInvalidated ? 'invalidated' : 'failed', + 'cdn' => $this->cdnStatus, + 'durationMs' => $this->durationMs, + ]; + } +} diff --git a/src/Log/Context/LogSessionBrokenContext.php b/src/Log/Context/LogSessionBrokenContext.php new file mode 100644 index 00000000..9da72f8a --- /dev/null +++ b/src/Log/Context/LogSessionBrokenContext.php @@ -0,0 +1,27 @@ + $tags */ + public function __construct( + public readonly array $tags, + ) { + } +} diff --git a/src/Log/Context/ManualPurgeContext.php b/src/Log/Context/ManualPurgeContext.php new file mode 100644 index 00000000..ed126567 --- /dev/null +++ b/src/Log/Context/ManualPurgeContext.php @@ -0,0 +1,24 @@ + */ + #[Override] + public function jsonSerialize(): array + { + return ['result' => $this->purged ? 'purged' : 'failed']; + } +} diff --git a/src/Log/Context/ManualStoreContext.php b/src/Log/Context/ManualStoreContext.php new file mode 100644 index 00000000..4b19af16 --- /dev/null +++ b/src/Log/Context/ManualStoreContext.php @@ -0,0 +1,25 @@ + */ + #[Override] + public function jsonSerialize(): array + { + return ['result' => $this->stored ? 'stored' : 'failed']; + } +} diff --git a/src/Log/Context/PurgeContext.php b/src/Log/Context/PurgeContext.php new file mode 100644 index 00000000..39f3bd94 --- /dev/null +++ b/src/Log/Context/PurgeContext.php @@ -0,0 +1,21 @@ + $tags */ + public function __construct( + public readonly string $uri, + public readonly array $tags, + public readonly int|null $ttl, + public readonly bool $saved, + ) { + } +} diff --git a/src/Log/Context/SaveDonutViewContext.php b/src/Log/Context/SaveDonutViewContext.php new file mode 100644 index 00000000..0d5f40d3 --- /dev/null +++ b/src/Log/Context/SaveDonutViewContext.php @@ -0,0 +1,25 @@ + $tags */ + public function __construct( + public readonly string $uri, + public readonly array $tags, + public readonly int|null $ttl, + public readonly bool $saved, + ) { + } +} diff --git a/src/Log/Context/SaveEtagContext.php b/src/Log/Context/SaveEtagContext.php new file mode 100644 index 00000000..5484202c --- /dev/null +++ b/src/Log/Context/SaveEtagContext.php @@ -0,0 +1,26 @@ + $tags */ + public function __construct( + public readonly string $uri, + public readonly string $etag, + public readonly array $tags, + public readonly int|null $ttl, + public readonly bool $saved, + ) { + } +} diff --git a/src/Log/Context/SaveValueContext.php b/src/Log/Context/SaveValueContext.php new file mode 100644 index 00000000..0a9fd0a2 --- /dev/null +++ b/src/Log/Context/SaveValueContext.php @@ -0,0 +1,25 @@ + $tags */ + public function __construct( + public readonly string $uri, + public readonly array $tags, + public readonly int|null $ttl, + public readonly bool $saved, + ) { + } +} diff --git a/src/Log/Context/SaveViewContext.php b/src/Log/Context/SaveViewContext.php new file mode 100644 index 00000000..8b1ae6ba --- /dev/null +++ b/src/Log/Context/SaveViewContext.php @@ -0,0 +1,25 @@ + $tags */ + public function __construct( + public readonly string $uri, + public readonly array $tags, + public readonly int|null $ttl, + public readonly bool $saved, + ) { + } +} diff --git a/src/Log/NullSemanticLogger.php b/src/Log/NullSemanticLogger.php new file mode 100644 index 00000000..7380e012 --- /dev/null +++ b/src/Log/NullSemanticLogger.php @@ -0,0 +1,59 @@ +depth === 0; + } + + #[Override] + public function open(AbstractContext $context): string + { + if ($this->broken) { + return ''; + } + + try { + $id = $this->logger->open($context); + $this->depth++; + + return $id; + } catch (Throwable) { + $this->broken = true; + + return ''; + } + } + + #[Override] + public function event(AbstractContext $context): void + { + if ($this->broken) { + return; + } + + try { + $this->logger->event($context); + } catch (Throwable) { + $this->broken = true; + } + } + + #[Override] + public function close(AbstractContext $context, string $openId): void + { + if ($this->broken || $openId === '') { + return; + } + + try { + $this->logger->close($context, $openId); + if ($this->depth > 0) { + $this->depth--; + } + } catch (Throwable) { + $this->broken = true; + } + } + + /** {@inheritDoc} */ + #[Override] + public function flush(array $links = []): LogJson + { + try { + $log = $this->logger->flush($links); + $this->broken = false; + $this->depth = 0; + + return $log; + } catch (Throwable $e) { + // The delegate's internal state may be dirty (e.g. an unclosed session). + // Replace it with a fresh logger so the next session recovers, and never + // surface the failure to the cache caller. + $this->logger = new SemanticLogger(); + $this->broken = false; + $this->depth = 0; + + try { + // Leave a tombstone for the wiped session: an empty flush would read + // as "no cache activity", hiding that records were lost. + $sentinel = new LogSessionBrokenContext($e->getMessage() !== '' ? $e->getMessage() : $e::class); + $openId = $this->logger->open($sentinel); + $this->logger->close($sentinel, $openId); + + return $this->logger->flush($links); + } catch (Throwable) { // @codeCoverageIgnoreStart + return new LogJson(self::EMPTY_SCHEMA_URL, [], [], [], $links); // @codeCoverageIgnoreEnd + } + } + } + + /** + * Serialize without session state (no live log carried across serialization) + * + * @return array + */ + public function __serialize(): array + { + return []; + } + + /** + * Session state is never carried across serialization, so the payload is ignored. + * + * @param array $data + * + * @SuppressWarnings("PHPMD.UnusedFormalParameter") + */ + public function __unserialize(array $data): void + { + $this->logger = new SemanticLogger(); + $this->broken = false; + } +} diff --git a/src/Log/SafeSemanticLoggerProvider.php b/src/Log/SafeSemanticLoggerProvider.php new file mode 100644 index 00000000..bad8ab44 --- /dev/null +++ b/src/Log/SafeSemanticLoggerProvider.php @@ -0,0 +1,29 @@ + + */ +final class SafeSemanticLoggerProvider implements ProviderInterface +{ + #[Override] + public function get(): SemanticLoggerInterface + { + return new SafeSemanticLogger(new SemanticLogger()); + } +} diff --git a/src/NullRepositoryLogger.php b/src/NullRepositoryLogger.php new file mode 100644 index 00000000..f232ae14 --- /dev/null +++ b/src/NullRepositoryLogger.php @@ -0,0 +1,35 @@ +logger->log('put-query-repository', ['uri' => (string) $ro->uri]); + // A top-level put is a direct (non-AOP) cache write with no enclosing scope, so its + // save events would be dropped at flush. Wrap it in a manual_store scope so the write + // stays visible. A put nested inside a request GET or a write command keeps emitting + // its save events under that scope, unchanged. + if ($this->logger instanceof SafeSemanticLogger && $this->logger->isTopLevel()) { + $openId = $this->logger->open(new ManualStoreContext((string) $ro->uri)); + $stored = false; + try { + return $stored = $this->doPut($ro); + } finally { + $this->logger->close(new ManualStoreResultContext($stored), $openId); + } + } + + return $this->doPut($ro); + } + + private function doPut(ResourceObject $ro): bool + { $this->storage->deleteEtag($ro->uri); if ($ro->code === 200) { $this->setCacheDependency($ro); @@ -108,7 +134,20 @@ public function get(AbstractUri $uri): ResourceState|null #[Override] public function purge(AbstractUri $uri) { - $this->logger->log('purge-query-repository', ['uri' => (string) $uri]); + // A top-level purge is an application-initiated (manual) cache bust: wrap it in a + // manual_purge scope so it stands out from automatic invalidation. A purge nested + // inside a request GET or a write command stays an ordinary purge event there. + if ($this->logger instanceof SafeSemanticLogger && $this->logger->isTopLevel()) { + $openId = $this->logger->open(new ManualPurgeContext((string) $uri)); + $purged = false; + try { + return $purged = $this->storage->deleteEtag($uri); + } finally { + $this->logger->close(new ManualPurgeResultContext($purged), $openId); + } + } + + $this->logger->event(new PurgeContext((string) $uri)); return $this->storage->deleteEtag($uri); } @@ -137,7 +176,8 @@ private function getExpiryTime(ResourceObject $ro, Cacheable|null $cacheable = n return $this->getExpiryAtSec($ro, $cacheable); } - return $cacheable->expirySecond ?: $this->expiry->getTime($cacheable->expiry); + // A user-supplied expirySecond may be negative; the schemas declare "minimum": 0 + return max(0, $cacheable->expirySecond ?: $this->expiry->getTime($cacheable->expiry)); } private function getExpiryAtSec(ResourceObject $ro, Cacheable $cacheable): int @@ -151,6 +191,7 @@ private function getExpiryAtSec(ResourceObject $ro, Cacheable $cacheable): int /** @var string $expiryAt */ $expiryAt = $ro->body[$cacheable->expiryAt]; - return (int) strtotime($expiryAt) - time(); + // A past expiryAt means "already expired": TTL 0 + return max(0, (int) strtotime($expiryAt) - time()); } } diff --git a/src/RefreshInterceptor.php b/src/RefreshInterceptor.php index 14adb17b..acaba14c 100644 --- a/src/RefreshInterceptor.php +++ b/src/RefreshInterceptor.php @@ -5,8 +5,11 @@ namespace BEAR\QueryRepository; use BEAR\QueryRepository\Exception\ReturnValueIsNotResourceObjectException; +use BEAR\QueryRepository\Log\Context\CommandResultContext; +use BEAR\QueryRepository\Log\NullSemanticLogger; use BEAR\Resource\Code; use BEAR\Resource\ResourceObject; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Override; use Ray\Aop\MethodInterceptor; use Ray\Aop\MethodInvocation; @@ -26,9 +29,13 @@ */ final readonly class RefreshInterceptor implements MethodInterceptor { + private CommandContextFactory $commandContextFactory; + public function __construct( private RefreshAnnotatedCommand $command, + private SemanticLoggerInterface $logger = new NullSemanticLogger(), ) { + $this->commandContextFactory = new CommandContextFactory(); } #[Override] @@ -40,8 +47,15 @@ public function invoke(MethodInvocation $invocation): ResourceObject throw new ReturnValueIsNotResourceObjectException($invocation->getThis()::class); // @codeCoverageIgnore } - if ($ro->code < Code::BAD_REQUEST) { - $this->command->command($invocation, $ro); + // Open the scope even for a failed write: a 4xx command_result with no invalidation + // events records that the purge/refresh was correctly skipped. + $openId = $this->logger->open(($this->commandContextFactory)($invocation, 'RefreshInterceptor')); + try { + if ($ro->code < Code::BAD_REQUEST) { + $this->command->command($invocation, $ro); + } + } finally { + $this->logger->close(new CommandResultContext($ro->code), $openId); } return $ro; diff --git a/src/RepositoryLogger.php b/src/RepositoryLogger.php index 29be391e..ab7bb88d 100644 --- a/src/RepositoryLogger.php +++ b/src/RepositoryLogger.php @@ -9,12 +9,17 @@ use function array_map; use function implode; +use function is_string; use function json_encode; use const JSON_UNESCAPED_SLASHES; use const PHP_EOL; -final class RepositoryLogger implements RepositoryLoggerInterface, Stringable +/** + * @deprecated Since the SemanticLogger migration; use {@see \Koriym\SemanticLogger\SemanticLogger}. + * @psalm-suppress DeprecatedInterface Deprecated class intentionally implements deprecated interfaces. + */ +final class RepositoryLogger implements StructuredRepositoryLoggerInterface, Stringable { /** @var list> */ private array $logs = []; @@ -37,6 +42,33 @@ public function reset(): void $this->logs = []; } + /** + * {@inheritDoc} + */ + #[Override] + public function getLogs(): array + { + return $this->logs; + } + + /** + * {@inheritDoc} + */ + #[Override] + public function getOps(): array + { + return array_map( + /** @param array $log */ + static function (array $log): string { + /** @var mixed $op */ + $op = $log['op'] ?? ''; + + return is_string($op) ? $op : ''; + }, + $this->logs, + ); + } + #[Override] public function __toString(): string { diff --git a/src/RepositoryLoggerInterface.php b/src/RepositoryLoggerInterface.php index c696bbff..0ad915b9 100644 --- a/src/RepositoryLoggerInterface.php +++ b/src/RepositoryLoggerInterface.php @@ -4,6 +4,12 @@ namespace BEAR\QueryRepository; +/** + * @deprecated Since the SemanticLogger migration. Cache logging now uses + * {@see \Koriym\SemanticLogger\SemanticLoggerInterface} with typed Context objects and a + * nested open/event/close tree. This flat interface is retained only for backward + * compatibility and no longer receives internal cache events. + */ interface RepositoryLoggerInterface { /** @param array $context */ diff --git a/src/ResourceStorage.php b/src/ResourceStorage.php index 62fea5b1..b28d959e 100644 --- a/src/ResourceStorage.php +++ b/src/ResourceStorage.php @@ -4,25 +4,38 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\Context\InvalidateContext; +use BEAR\QueryRepository\Log\Context\ManualInvalidateContext; +use BEAR\QueryRepository\Log\Context\SaveDonutContext; +use BEAR\QueryRepository\Log\Context\SaveDonutViewContext; +use BEAR\QueryRepository\Log\Context\SaveEtagContext; +use BEAR\QueryRepository\Log\Context\SaveValueContext; +use BEAR\QueryRepository\Log\Context\SaveViewContext; +use BEAR\QueryRepository\Log\SafeSemanticLogger; use BEAR\RepositoryModule\Annotation\EtagPool; use BEAR\RepositoryModule\Annotation\ResourceObjectPool; use BEAR\Resource\AbstractUri; use BEAR\Resource\RequestInterface; use BEAR\Resource\ResourceObject; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Override; use Ray\Di\Di\Set; use Ray\Di\ProviderInterface; use Symfony\Component\Cache\Adapter\TagAwareAdapterInterface; +use Throwable; use function array_merge; use function array_unique; use function array_values; use function assert; use function explode; +use function hrtime; use function implode; use function is_array; +use function max; use function preg_match; use function preg_match_all; +use function round; use function sprintf; use function str_starts_with; use function strtoupper; @@ -31,7 +44,7 @@ /** * @psalm-type Props = array{ - * logger: RepositoryLoggerInterface, + * logger: SemanticLoggerInterface, * purger:PurgerInterface, * uriTag: UriTag, * saver: ResourceStorageSaver, @@ -57,6 +70,12 @@ final class ResourceStorage implements ResourceStorageInterface */ private const ENTITY_TAG_PATTERN = '(?:W\/)?"[^"]*"|[^,"]+'; + /** + * CDN status when the purge did not throw, indexed by (int) no-CDN: + * [0] a configured purger ran -> "purged", [1] NullPurger -> "skipped" + */ + private const CDN_OK_STATUS = ['purged', 'skipped']; + /** @var ProviderInterface */ private ProviderInterface $roPoolProvider; @@ -70,7 +89,7 @@ final class ResourceStorage implements ResourceStorageInterface * @param ProviderInterface $etagPoolProvider */ public function __construct( - private RepositoryLoggerInterface $logger, + private SemanticLoggerInterface $logger, private PurgerInterface $purger, private UriTagInterface $uriTag, private ResourceStorageSaver $saver, @@ -190,12 +209,67 @@ public function deleteEtag(AbstractUri $uri) #[Override] public function invalidateTags(array $tags): bool { - $this->logger->log('invalidate-etag', ['tags' => $tags]); - $valid1 = $this->roPool->invalidateTags($tags); - $valid2 = $this->etagPool->invalidateTags($tags); - ($this->purger)(implode(' ', $tags)); + $start = hrtime(true); + $roOk = $this->roPool->invalidateTags($tags); + $etagOk = $this->etagPool->invalidateTags($tags); + + // The CDN purge is fail-closed: a purge failure must surface so a write does not + // silently leave stale CDN content. The local pools are invalidated first, and the + // outcome is logged (cdn=failed) before the exception is re-thrown to the caller. + $purgerError = null; + try { + ($this->purger)(implode(' ', $tags)); + } catch (Throwable $e) { + $purgerError = $e; + } + + $result = new InvalidateContext( + $tags, + roPoolInvalidated: $roOk, + etagPoolInvalidated: $etagOk, + cdnStatus: $purgerError === null ? $this->getCdnOkStatus() : 'failed', + durationMs: round((hrtime(true) - $start) / 1_000_000, 3), + ); + + $this->logInvalidation($result, $tags); + + if ($purgerError !== null) { + throw $purgerError; + } + + return $roOk && $etagOk; + } + + /** + * CDN status when the purge did not throw: "skipped" when no CDN is configured + * (NullPurger), "purged" when a real purger ran — a branch-free lookup + * + * @return "purged"|"skipped" + */ + private function getCdnOkStatus(): string + { + return self::CDN_OK_STATUS[(int) ($this->purger instanceof NullPurger)]; + } + + /** + * Record an invalidation outcome + * + * A top-level invalidation is a direct (non-AOP) call with no enclosing scope, so the + * event would be dropped at flush. Root it in a manual_invalidate scope whose close + * carries the outcome. Nested invalidations (inside a GET or a command) stay events. + * + * @param list $tags + */ + private function logInvalidation(InvalidateContext $result, array $tags): void + { + if ($this->logger instanceof SafeSemanticLogger && $this->logger->isTopLevel()) { + $openId = $this->logger->open(new ManualInvalidateContext($tags)); + $this->logger->close($result, $openId); + + return; + } - return $valid1 && $valid2; + $this->logger->event($result); } /** @@ -206,14 +280,16 @@ public function invalidateTags(array $tags): bool #[Override] public function saveValue(ResourceObject $ro, int $ttl) { + $ttl = max(0, $ttl); /** @psalm-suppress MixedAssignment $body */ $body = $this->evaluateBody($ro->body); $value = ResourceState::create($ro, $body, null); $key = $this->getUriKey($ro->uri, self::KEY_RO); $tags = $this->getTags($ro); - $this->logger->log('save-value', ['uri' => (string) $ro->uri, 'tags' => $tags, 'ttl' => $ttl]); + $saved = $this->saver->__invoke($key, $value, $this->roPool, $tags, $ttl); + $this->logger->event(new SaveValueContext((string) $ro->uri, $tags, $ttl, $saved)); - return $this->saver->__invoke($key, $value, $this->roPool, $tags, $ttl); + return $saved; } /** @@ -224,14 +300,16 @@ public function saveValue(ResourceObject $ro, int $ttl) #[Override] public function saveView(ResourceObject $ro, int $ttl) { - $this->logger->log('save-view', ['uri' => (string) $ro->uri, 'ttl' => $ttl]); + $ttl = max(0, $ttl); /** @psalm-suppress MixedAssignment $body */ $body = $this->evaluateBody($ro->body); $value = ResourceState::create($ro, $body, $ro->view); $key = $this->getUriKey($ro->uri, self::KEY_RO); $tags = $this->getTags($ro); + $saved = $this->saver->__invoke($key, $value, $this->roPool, $tags, $ttl); + $this->logger->event(new SaveViewContext((string) $ro->uri, $tags, $ttl, $saved)); - return $this->saver->__invoke($key, $value, $this->roPool, $tags, $ttl); + return $saved; } /** @@ -240,21 +318,27 @@ public function saveView(ResourceObject $ro, int $ttl) #[Override] public function saveDonut(AbstractUri $uri, ResourceDonut $donut, int|null $sMaxAge, array $headerKeys): void { + // Despite the legacy parameter name (kept for BC), this argument carries the donut + // template entry TTL (putStatic passes $ttl, putDonut passes $donutTtl), never a CDN s-maxage. + $sMaxAge = $sMaxAge === null ? null : max(0, $sMaxAge); $key = $this->getUriKey($uri, self::KEY_DONUT); - $this->logger->log('save-donut', ['uri' => (string) $uri, 'sMaxAge' => $sMaxAge]); - $result = $this->saver->__invoke($key, $donut, $this->roPool, $headerKeys, $sMaxAge); - assert($result, 'Donut save failed.'); + $saved = $this->saver->__invoke($key, $donut, $this->roPool, $headerKeys, $sMaxAge); + // saved=false is logged, not asserted: a quiet store failure must stay observable + // in the log (an assert here would throw AFTER the event, contradicting it). + $this->logger->event(new SaveDonutContext((string) $uri, $headerKeys, $sMaxAge, $saved)); } #[Override] public function saveDonutView(ResourceObject $ro, int|null $ttl): bool { + $ttl = $ttl === null ? null : max(0, $ttl); $resourceState = ResourceState::create($ro, [], $ro->view); $key = $this->getUriKey($ro->uri, self::KEY_RO); $tags = $this->getTags($ro); - $this->logger->log('save-donut-view', ['uri' => (string) $ro->uri, 'surrogateKeys' => $tags, 'sMaxAge' => $ttl]); + $saved = $this->saver->__invoke($key, $resourceState, $this->roPool, $tags, $ttl); + $this->logger->event(new SaveDonutViewContext((string) $ro->uri, $tags, $ttl, $saved)); - return $this->saver->__invoke($key, $resourceState, $this->roPool, $tags, $ttl); + return $saved; } /** @return list */ @@ -327,13 +411,14 @@ private function getVary(): string #[Override] public function saveEtag(AbstractUri $uri, string $etag, string $surrogateKeys, int|null $ttl): void { + $ttl = $ttl === null ? null : max(0, $ttl); $tags = $surrogateKeys !== '' ? explode(' ', $surrogateKeys) : []; $tags[] = (new UriTag())($uri); /** @var list $uniqueTags */ $uniqueTags = array_values(array_unique($tags)); - $this->logger->log('save-etag', ['uri' => (string) $uri, 'etag' => $etag, 'surrogateKeys' => $uniqueTags]); // The header value is a quoted entity-tag; the pool key is the bare opaque-tag - $this->saver->__invoke(trim($etag, '"'), 'etag', $this->etagPool, $uniqueTags, $ttl); + $saved = $this->saver->__invoke(trim($etag, '"'), 'etag', $this->etagPool, $uniqueTags, $ttl); + $this->logger->event(new SaveEtagContext((string) $uri, $etag, $uniqueTags, $ttl, $saved)); } public function __serialize(): array diff --git a/src/StructuredRepositoryLoggerInterface.php b/src/StructuredRepositoryLoggerInterface.php new file mode 100644 index 00000000..b46aaad1 --- /dev/null +++ b/src/StructuredRepositoryLoggerInterface.php @@ -0,0 +1,36 @@ + ..., ...$context]` array passed to log(). + * + * @return list> + */ + public function getLogs(): array; + + /** + * Return the operation names of all log entries in insertion order + * + * Convenience accessor for asserting the sequence of cache operations. + * + * @return list + */ + public function getOps(): array; +} diff --git a/tests/CACHE_DEPENDENCY_TESTS.md b/tests/CACHE_DEPENDENCY_TESTS.md index e809baf0..a4857c49 100644 --- a/tests/CACHE_DEPENDENCY_TESTS.md +++ b/tests/CACHE_DEPENDENCY_TESTS.md @@ -13,7 +13,9 @@ LevelOne → LevelTwo → LevelThree purge(LevelThree) → LevelOne invalidated ``` -**Test:** `CacheDependencyTest::testDestroyByGrandChild` +**Test:** `CacheDependencyTest::testDestroyByGrandChild` (manual purge) and +`CacheDependencyTest::testWriteToGrandChildCascadesInvalidation` (the same cascade +driven by a write command: `LevelThree::onPut` carries `#[Purge]`) ### Parent-Child Dependencies @@ -79,7 +81,123 @@ invalidateTags([uriTag('page://self/html/blog-posting')]) → BlogPosting invali | `UriTag::__invoke()` | `UriTagTest::testInvoke` | URI to tag string conversion | | `UriTag::fromAssoc()` | `UriTagTest::testFromAssoc` | Generate tags from array data | | `SurrogateKeys` | `SurrogateKeysTest` | Aggregate tags from multiple resources | -| `RepositoryLogger` | `RepositoryLoggerTest` | Log formatting with arrays | +| Tree helpers | `SemanticLogTreeTrait` | Validate + collect types / depth from the log tree | + +## Observability (Koriym.SemanticLogger) + +Cache behavior is observed through [Koriym.SemanticLogger](https://github.com/koriym/Koriym.SemanticLogger): +an **open / event / close** model whose nested structure *is* the embed/dependency +tree. A resource GET opens a scope (`CacheInterceptor` / `AbstractDonutCacheInterceptor`); +embedded child GETs nest under it; the scope closes with the hit/miss outcome. +Saves, dependencies and invalidations are recorded as events inside the active scope. +Typed `AbstractContext` subclasses live in `src/Log/Context/` and each carries a +`SCHEMA_URL` resolved against `docs/schemas/context/`. + +| Context (type) | Kind | Emitted by | Meaning | +|----|----|-----------|---------| +| `get` | open | `CacheInterceptor`, `AbstractDonutCacheInterceptor` | A resource/donut GET scope (children nest under it) | +| `cache_hit` / `cache_miss` (`layer`) | close/event | interceptors, `DonutRepository` | The lookup outcome (`layer`: resource / donut / donut-view) | +| `command` (`method`/`annotations`/`source`) | open | `CommandInterceptor`, `DonutCommandInterceptor`, `RefreshInterceptor` (all via the shared `CommandContextFactory`) | 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 | `CacheDependency::depends()` | A dependency-graph edge | +| `save_value` / `save_view` / `save_etag` / `save_donut` / `save_donut_view` | event | `ResourceStorage` | What was stored, with `tags`, `ttl` (seconds until expiry; 0/null = no expiry set) and the `saved` outcome | +| `invalidate` (`tags`/`roPool`/`etagPool`/`cdn`/`durationMs`) | event | `ResourceStorage::invalidateTags()` | Per-target outcome as status words: `roPool`/`etagPool` are `invalidated`\|`failed`; `cdn` is tri-state: `purged` (a configured purger ran), `failed` (the purge threw — fail-closed: local pools are invalidated first, then the exception propagates), `skipped` (NullPurger, no CDN configured). Pre-write cleanup vs real invalidation is decided by same-scope tag correlation — see the flow example below | +| `purge` | event | `QueryRepository::purge()` | An explicit purge request | +| `put_skipped` (`uri`/`reason`[/`code`]) | event | `CacheInterceptor`, `AbstractDonutCacheInterceptor`, `DonutRepository` | A miss was not followed by a put (`reason`: `etag-present` / `error-code` with the actual response `code` / `not-cacheable` for a donut page served from its template) | +| `cache_error` (`uri`/`operation`/`error`) | event | `CacheInterceptor`, `AbstractDonutCacheInterceptor` | The cache layer itself threw (e.g. cache server down); `operation` is the failing side (`read` / `write`); a `cache_miss` after it is a degraded cache, not a cold one | +| `put_donut` / `refresh_donut` | event | `DonutRepository` | Donut store / re-render from a template hit | +| `log_session_broken` (`reason`) | open/close | `SafeSemanticLogger::flush()` | Sentinel: the previous logging session was broken (e.g. LIFO violation) and its records were discarded; the flush containing it holds ONLY this scope — that window's cache activity is unknown, not absent | + +(SemanticLogger derives entry ids as `{type}_{n}` and constrains them to +`^[a-z_]+_[0-9]+$`, so context `type`s use underscores; the donut `layer` value +`donut-view` is a field value, not an id, so it keeps its hyphen.) + +### Reading the tree (human + AI) + +`php demo/run-dependency.php` renders the session with `vendor/bin/stree`'s +`Stree\TreeRenderer`. The 3-level chain appears as native nesting — the embed +structure is the log structure, no reconstruction. Within a node the JSON groups +nested `open`s separately from `events` (they are not interleaved +chronologically); the emission order is: the leading `invalidate` (pre-write +cleanup — every `QueryRepository::doPut()` deleteEtags first), then the nested +child GET scopes run to completion, then the parent's `depends_on` / `save_*` +(the parent materializes its embeds before it can register and store): + +```text +get uri=page://self/dep/level-one +├── invalidate tags=[_dep_level-one_] [event] (pre-write cleanup) +├── get uri=page://self/dep/level-two +│ ├── invalidate tags=[_dep_level-two_] [event] (pre-write cleanup) +│ ├── get uri=page://self/dep/level-three +│ │ ├── invalidate → save_etag → save_value [events] +│ │ └── (close) cache_miss layer=resource +│ ├── depends_on parent=.../level-two child=.../level-three [event] +│ ├── save_etag → save_value [events] +│ └── (close) cache_miss layer=resource +├── depends_on parent=.../level-one child=.../level-two childTags=[_dep_level-two_, _dep_level-three_] [event] +├── save_etag uri=.../level-one tags=[...] saved=true [event] +├── save_value uri=.../level-one tags=[..., _dep_level-three_] ttl=31536000 saved=true [event] +└── (close) cache_miss layer=resource +``` + +The leading `invalidate` uses the resource's own URI tag, which is also its +parents' surrogate key — so a child refill visibly purges the parent entry +before both are rebuilt, by design. + +Pre-write cleanup vs real invalidation is decided by tag correlation, not by +scope type: scanning forward from an `invalidate` within the SAME scope's +event stream, it is pre-write cleanup iff the first `save_*` event whose +`tags` include the invalidate's tags is reached with only `depends_on` events +for the same resource in between — regardless of the enclosing scope type +(`get` or `command`; a `#[Refresh]` command's second put() runs inside the +command scope, so a cleanup invalidate can appear there too). If another +`invalidate` or `purge` intervenes before a matching `save_*`, it is a real +invalidation — a `#[Refresh]` command shows both shapes: the purge's +invalidate is real, the re-put's own deleteEtag is cleanup. In donut scopes +match against `save_etag`/`save_donut_view`: `save_donut`'s tags may exclude +the URI tag (a known ordering limitation); when neither `save_etag` nor +`save_donut_view` is present in the scope (a donut resource declaring no +Surrogate-Key), the classification is undecidable from the log alone — this +overrides the rule above: do not conclude a real invalidation merely from the +absence of a matching `save_*`. +Note the tree JSON does not interleave a scope's events with its nested scopes +chronologically — within one scope events are time-ordered, but across the +events/open-children boundary no shared sequence exists; use scope nesting and +the next GET's hit/miss as ground truth for final state. + +A write request opens a `command` scope (`method=onPut`, its `#[Refresh]`/`#[Purge]` +annotations) with the resulting `purge` / `invalidate` events nested beneath — so +the cause and the verified effect are both in one subtree. Scenario 3 of +`demo/run-dependency.php` demonstrates exactly this: a PUT on level-three (whose +`onPut` carries `#[Purge]`) drives the cascade, while scenario 6 shows the other +entry kind — a direct `purge()` call rooted in a top-level `manual_purge` scope. + +## Schema Validation (Drift Detection) + +`SemanticLogTreeTrait::flushAndValidate()` flushes the logger and runs +`Koriym\SemanticLogger\SemanticLogValidator` against `docs/schemas/context`, +validating every context against its `SCHEMA_URL`. It runs in the `tearDown()` of +the major cache tests, so any divergence between an emitted context and its schema +fails the suite immediately. + +`SemanticLogSchemaTest` pins the contract from both sides: + +| Test | Verifies | +|------|----------| +| `testDependencyChainValidatesAndNestsAsEmbedTree` | A real dependency run validates and nests ≥3 deep, with `cache_miss`/`depends_on`/`invalidate`/`save_value` present | +| `testCommandScopeRecordsCausality` | A write opens a `command` scope recording `onPut` and its annotations | +| `testNon200GetLogsPutSkippedWithActualCode` | A non-200 GET records `put_skipped` with `reason=error-code` and the actual response `code`, plus a `purge` event | +| `testValidatorRejectsContextViolatingItsSchema` | A `cache_hit` without `layer` is rejected (proves drift is caught) | + +`ResourceStorageTest` pins the invalidation outcome and `GracefulLoggingTest` +pins resilience: + +| Test | Verifies | +|------|----------| +| `testInvalidateTagsWithNullPurgerLogsCdnSkipped` | With the default NullPurger (no CDN) `cdn` is `skipped`; `roPool`/`etagPool` are `invalidated`, `durationMs` is recorded | +| `testInvalidateTagsLogsCdnPurgedWithConfiguredPurger` | A configured purger that runs without error logs `cdn` = `purged` | +| `testInvalidateTagsFailsClosedWhenPurgerFails` | A CDN purger outage is logged as `cdn=failed` after local invalidation, then the purge exception propagates (fail-closed) | +| `SafeSemanticLoggerTest::testRecoversToFreshSessionAfterFlushFailure` / `testLifoViolationBreaksSessionThenFlushRecovers` | A discarded session flushes to a `log_session_broken` sentinel (not silent-empty); the next session logs normally | +| `GracefulLoggingTest::testCacheWorksWhenLoggerAlwaysThrows` | A logger that throws on every call never breaks cache reads/writes (SafeSemanticLogger) | ## ETag Invalidation Verification @@ -92,6 +210,32 @@ All dependency tests verify both resource cache and ETag invalidation: | `testUnrelatedResourcesAreIndependent` | Invalidated ETag gone, unrelated ETag preserved | | `testMultipleParentsDependOnSameChild` | Both parents' ETags invalidated | +## Known Limitations (Deliberate Scope) + +- **Request-end flush / concurrent long-running runtimes.** The logger is an injector + singleton with a stack-based session, and (as before this migration) this package does + not flush/reset per request. Safe operation therefore requires recreating the + injector/logger per request OR flushing at each request boundary; under + Swoole/RoadRunner a host must flush at the boundary itself. Under *concurrent* + coroutines sharing the one singleton, an interleaved open/close violates LIFO and + `SafeSemanticLogger` marks the session broken — so the current request's log is + **discarded** and its flush returns only a `log_session_broken` sentinel (the + wipe is visible, not silent). Cache behavior is unaffected + (logging is a best-effort side-channel) and the next `flush()` recovers a fresh + session (see `SafeSemanticLoggerTest`). Making the logger request/coroutine-scoped + (so concurrent sessions cannot cross-nest or drop) is the robust fix and is + intentionally deferred to the host flush-lifecycle work. +- **Donut-view hit vs. rebuild.** The donut GET scope closes as `cache_hit` (layer + `donut-view`) whenever a ResourceObject is served — including when it was rebuilt + from a cached donut template (the close reports only the final layer's outcome, + also stated in `cache_hit.json`). The two are still distinguishable by the presence of a + `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`. +- **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. + ## Fake Resources for Testing Located in `tests/Fake/fake-app/src/Resource/Page/Dep/`: @@ -100,7 +244,7 @@ Located in `tests/Fake/fake-app/src/Resource/Page/Dep/`: |----------|--------|---------| | `LevelOne` | `LevelTwo` | Top of 3-level chain | | `LevelTwo` | `LevelThree` | Middle of chain | -| `LevelThree` | - | Leaf node | +| `LevelThree` | - | Leaf node; `onPut` carries `#[Purge]` (command-driven cascade, demo scenario 3) | | `ParentA` | `ChildC` | Multiple parent test | | `ParentB` | `ChildC` | Multiple parent test | | `ChildC` | - | Shared child resource | diff --git a/tests/CacheDependencyTest.php b/tests/CacheDependencyTest.php index dafd400a..e36a8f7a 100644 --- a/tests/CacheDependencyTest.php +++ b/tests/CacheDependencyTest.php @@ -59,6 +59,25 @@ public function testDestroyByGrandChild(): void $this->assertFalse($this->storage->hasEtag($etag3)); } + /** + * The same grandchild cascade as testDestroyByGrandChild, but driven by a write + * command instead of a manual purge: LevelThree::onPut's #[Purge] busts + * level-three and, via the surrogate-key tags, its parents. This pins the + * command-driven invalidation flow demonstrated in demo/run-dependency.php. + */ + public function testWriteToGrandChildCascadesInvalidation(): void + { + $this->resource->get('page://self/dep/level-one'); + $one1 = $this->repository->get(new Uri('page://self/dep/level-one')); + $this->assertInstanceOf(ResourceState::class, $one1); + $etag1 = $one1->headers[Header::ETAG]; + $this->resource->put('page://self/dep/level-three'); + $this->assertNull($this->repository->get(new Uri('page://self/dep/level-one'))); + $this->assertNull($this->repository->get(new Uri('page://self/dep/level-two'))); + $this->assertNull($this->repository->get(new Uri('page://self/dep/level-three'))); + $this->assertFalse($this->storage->hasEtag($etag1)); + } + /** * Test that resources in unrelated dependency chains are independent. * diff --git a/tests/DonutCacheInterceptorTest.php b/tests/DonutCacheInterceptorTest.php index 36e53c01..5940669d 100644 --- a/tests/DonutCacheInterceptorTest.php +++ b/tests/DonutCacheInterceptorTest.php @@ -6,6 +6,7 @@ use BEAR\Resource\ResourceInterface; use FakeVendor\HelloWorld\Resource\Page\Html\BlogPostingDonut; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Madapaja\TwigModule\TwigModule; use PHPUnit\Framework\TestCase; use Ray\Di\Injector; @@ -15,8 +16,10 @@ class DonutCacheInterceptorTest extends TestCase { + use SemanticLogTreeTrait; + private ResourceInterface $resource; - private RepositoryLoggerInterface $logger; + private SemanticLoggerInterface $logger; protected function setUp(): void { @@ -31,16 +34,15 @@ protected function setUp(): void assert($injector instanceof Injector); $this->resource = $injector->getInstance(ResourceInterface::class); - $this->logger = $injector->getInstance(RepositoryLoggerInterface::class); + $this->logger = $injector->getInstance(SemanticLoggerInterface::class); parent::setUp(); } protected function tearDown(): void { - $log = ((string) $this->logger); - // error_log((string) $log); // uncomment to see the debug log - unset($log); + // Every emitted entry must conform to its context schema (drift detection) + $this->flushAndValidate($this->logger); } public function testInitialRequest(): string @@ -52,27 +54,38 @@ public function testInitialRequest(): string $view = (string) $blogPosting; $this->assertSame('blog-posting:1comment01', $view); + // save_donut records its invalidation tags: the Surrogate-Key header keys at put + // time (this resource sets none, so the entry is tagged with an empty list). + $tree = $this->flushAndValidate($this->logger); + $saveDonut = self::eventContextJsonOf($tree, 'save_donut'); + $this->assertNotNull($saveDonut); + $this->assertStringContainsString('"tags":[]', $saveDonut); + return $blogPosting->headers[Header::SURROGATE_KEY]; } /** @depends testInitialRequest */ public function testCached(): void { - // test cached - $this->logger->log('get'); + $this->logger->flush(); // drain the initial-request session + $blogPosting = $this->resource->get('page://self/html/blog-posting-donut'); assert($blogPosting instanceof BlogPostingDonut); - $log = (string) $this->logger; - // Verify key operations in JSON log format - $this->assertStringContainsString('"op":"try-donut-view"', $log); - $this->assertStringContainsString('"op":"try-donut"', $log); - $this->assertStringContainsString('"op":"no-donut-found"', $log); - $this->assertStringContainsString('"op":"put-donut"', $log); - $this->assertStringContainsString('"op":"put-query-repository"', $log); - $this->assertStringContainsString('"op":"save-etag"', $log); - $this->assertStringContainsString('"op":"save-value"', $log); - $this->assertStringContainsString('"op":"save-donut"', $log); - $this->assertStringContainsString('"op":"refresh-donut"', $log); + + // The whole tree validates, and the cached access reuses the donut structure + // (cache_hit) then rebuilds the view (refresh_donut) rather than a full miss. + $tree = $this->flushAndValidate($this->logger); + $types = self::collectTypes($tree); + $this->assertContains('get', $types); + $this->assertContains('cache_hit', $types); + $this->assertContains('refresh_donut', $types); + + // The page is not entire-content cacheable (putDonut): the refreshed view is + // served live and no page-level save follows — recorded as put_skipped. + $putSkipped = self::eventContextJsonOf($tree, 'put_skipped'); + $this->assertNotNull($putSkipped, 'the missing page-level save after refresh is explained'); + $this->assertStringContainsString('"reason":"not-cacheable"', $putSkipped); + $this->assertArrayNotHasKey('Age', $blogPosting->headers); $this->assertArrayNotHasKey(Header::CDN_CACHE_CONTROL, $blogPosting->headers); } diff --git a/tests/DonutCommandInterceptorTest.php b/tests/DonutCommandInterceptorTest.php index 96170d74..ca63b35f 100644 --- a/tests/DonutCommandInterceptorTest.php +++ b/tests/DonutCommandInterceptorTest.php @@ -7,6 +7,7 @@ use BEAR\Resource\Code; use BEAR\Resource\ResourceInterface; use BEAR\Sunday\Extension\Transfer\HttpCacheInterface as HttpCacheInterfaceAlias; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Madapaja\TwigModule\TwigModule; use PHPUnit\Framework\TestCase; use Ray\Di\Injector; @@ -19,8 +20,10 @@ class DonutCommandInterceptorTest extends TestCase { + use SemanticLogTreeTrait; + protected ResourceInterface $resource; - protected RepositoryLoggerInterface $logger; + protected SemanticLoggerInterface $logger; protected HttpCacheInterfaceAlias $httpCache; protected function setUp(): void @@ -30,7 +33,7 @@ protected function setUp(): void $module->override(new TwigModule([dirname(__DIR__) . '/tests/Fake/fake-app/var/templates'])); $injector = new Injector($module, __DIR__ . '/tmp'); $this->resource = $injector->getInstance(ResourceInterface::class); - $this->logger = $injector->getInstance(RepositoryLoggerInterface::class); + $this->logger = $injector->getInstance(SemanticLoggerInterface::class); $this->httpCache = $injector->getInstance(HttpCacheInterfaceAlias::class); parent::setUp(); @@ -38,9 +41,8 @@ protected function setUp(): void protected function tearDown(): void { - $log = ((string) $this->logger); - // error_log((string) $log); // uncomment to see the debug log - unset($log); + // Every emitted log entry must conform to the published schema (drift detection) + $this->flushAndValidate($this->logger); } public function testCommandInterceptorRefresh(): void @@ -55,11 +57,8 @@ public function testCommandInterceptorRefresh(): void $this->assertTrue($this->httpCache->isNotModified($server)); $ro1 = $this->resource->get('page://self/html/blog-posting?id=0'); $this->assertArrayHasKey('Age', $ro1->headers); - $this->logger->log('delete'); $this->resource->delete('page://self/html/blog-posting?id=0'); $this->assertFalse($this->httpCache->isNotModified($server)); - $this->logger->log('server:%s', $server); - $this->logger->log('get'); $ro = $this->resource->get('page://self/html/blog-posting?id=0'); $this->assertArrayHasKey('Age', $ro->headers); } @@ -79,6 +78,38 @@ public function testCommandInterceptorRefreshOnErrorCode(): void $this->assertArrayHasKey('Age', $ro->headers); } + public function testPutSkippedIsLoggedWhenResponseAlreadyHasEtag(): void + { + // SelfEtag presets its own ETag in onGet: the miss is intentionally NOT followed + // by a put, and the log must say so instead of looking like a lost write. + $this->logger->flush(); // drain the setUp session + $this->resource->get('page://self/html/self-etag'); + $tree = $this->flushAndValidate($this->logger); + + $skipped = self::eventContextJsonOf($tree, 'put_skipped'); + $this->assertNotNull($skipped, 'the intentional skip is recorded'); + $this->assertStringContainsString('"reason":"etag-present"', $skipped); + $close = self::closeContextJsonOf($tree, 'cache_miss'); + $this->assertNotNull($close, 'the scope still closes cache_miss (skip, not hit)'); + } + + public function testSaveDonutLogsHeaderTags(): void + { + // putStatic tags the donut entry with the Surrogate-Key header keys captured at + // put time; BlogPosting sets 'blog-posting-page' in onGet. + $this->resource->get('page://self/html/blog-posting?id=0'); + $tree = $this->flushAndValidate($this->logger); + + $saveDonut = self::eventContextJsonOf($tree, 'save_donut'); + $this->assertNotNull($saveDonut); + $this->assertStringContainsString('"blog-posting-page"', $saveDonut); + + // save_donut_view records its invalidation tags, including the resource's URI tag. + $saveDonutView = self::eventContextJsonOf($tree, 'save_donut_view'); + $this->assertNotNull($saveDonutView); + $this->assertStringContainsString('"_html_blog-posting_id=0"', $saveDonutView); + } + public function testCacheableResponse(): void { $ro = $this->resource->get('page://self/html/blog-posting-cache?id=0'); diff --git a/tests/DonutCommandRedisCacheTest.php b/tests/DonutCommandRedisCacheTest.php index 3ce976e6..ca3ac9da 100644 --- a/tests/DonutCommandRedisCacheTest.php +++ b/tests/DonutCommandRedisCacheTest.php @@ -6,6 +6,7 @@ use BEAR\Resource\ResourceInterface; use BEAR\Sunday\Extension\Transfer\HttpCacheInterface as HttpCacheInterfaceAlias; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Madapaja\TwigModule\TwigModule; use Ray\Di\Injector; @@ -25,7 +26,7 @@ protected function setUp(): void $module->override(new StorageRedisModule('127.0.0.1:6379')); $injector = new Injector($module, __DIR__ . '/tmp'); $this->resource = $injector->getInstance(ResourceInterface::class); - $this->logger = $injector->getInstance(RepositoryLoggerInterface::class); + $this->logger = $injector->getInstance(SemanticLoggerInterface::class); $httpCache = $injector->getInstance(HttpCacheInterfaceAlias::class); $unserializedHttpCache = unserialize(serialize($httpCache)); assert($unserializedHttpCache instanceof HttpCacheInterfaceAlias); diff --git a/tests/DonutQueryInterceptorPurgeTest.php b/tests/DonutQueryInterceptorPurgeTest.php index 0cdbe42a..cf00131e 100644 --- a/tests/DonutQueryInterceptorPurgeTest.php +++ b/tests/DonutQueryInterceptorPurgeTest.php @@ -7,6 +7,7 @@ use BEAR\Resource\ResourceInterface; use BEAR\Resource\ResourceObject; use BEAR\Resource\Uri; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Madapaja\TwigModule\TwigModule; use PHPUnit\Framework\TestCase; use Ray\Di\Injector; @@ -17,9 +18,11 @@ class DonutQueryInterceptorPurgeTest extends TestCase { + use SemanticLogTreeTrait; + private ResourceInterface $resource; private QueryRepository $repository; - private RepositoryLoggerInterface $logger; + private SemanticLoggerInterface $logger; protected function setUp(): void { @@ -35,16 +38,15 @@ protected function setUp(): void assert($injector instanceof Injector); $this->resource = $injector->getInstance(ResourceInterface::class); $this->repository = $injector->getInstance(QueryRepository::class); - $this->logger = $injector->getInstance(RepositoryLoggerInterface::class); + $this->logger = $injector->getInstance(SemanticLoggerInterface::class); parent::setUp(); } protected function tearDown(): void { - $log = ((string) $this->logger); - // error_log((string) $log); // uncomment to see the debug log - unset($log); + // Every emitted log entry must conform to the published schema (drift detection) + $this->flushAndValidate($this->logger); } public function testStatePurge(): void diff --git a/tests/DonutQueryInterceptorTest.php b/tests/DonutQueryInterceptorTest.php index 70a481d6..a7bfa87a 100644 --- a/tests/DonutQueryInterceptorTest.php +++ b/tests/DonutQueryInterceptorTest.php @@ -7,6 +7,7 @@ use BEAR\Resource\ResourceInterface; use FakeVendor\HelloWorld\Resource\Page\Html\BlogPosting; use FakeVendor\HelloWorld\Resource\Page\Html\Comment; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Madapaja\TwigModule\TwigModule; use PHPUnit\Framework\TestCase; use Ray\Di\Injector; @@ -17,8 +18,10 @@ class DonutQueryInterceptorTest extends TestCase { + use SemanticLogTreeTrait; + private ResourceInterface $resource; - private RepositoryLoggerInterface $logger; + private SemanticLoggerInterface $logger; protected function setUp(): void { @@ -33,16 +36,15 @@ protected function setUp(): void assert($injector instanceof Injector); $this->resource = $injector->getInstance(ResourceInterface::class); - $this->logger = $injector->getInstance(RepositoryLoggerInterface::class); + $this->logger = $injector->getInstance(SemanticLoggerInterface::class); parent::setUp(); } protected function tearDown(): void { - $log = ((string) $this->logger); - // error_log((string) $log); // uncomment to see the debug log - unset($log); + // Every emitted entry must conform to its context schema (drift detection) + $this->flushAndValidate($this->logger); } public function testInitialRequest(): string @@ -71,22 +73,18 @@ public function testSurrogateKey(string $surrogateKey): void /** @depends testInitialRequest */ public function testCached(): void { - // test cached - $this->logger->log('get'); + $this->logger->flush(); // drain any prior session + $blogPosting = $this->resource->get('page://self/html/blog-posting'); assert($blogPosting instanceof BlogPosting); - $log = (string) $this->logger; - // Verify key operations in JSON log format - $this->assertStringContainsString('"op":"try-donut-view"', $log); - $this->assertStringContainsString('"op":"try-donut"', $log); - $this->assertStringContainsString('"op":"no-donut-found"', $log); - $this->assertStringContainsString('"op":"put-donut"', $log); - $this->assertStringContainsString('"op":"put-query-repository"', $log); - $this->assertStringContainsString('"op":"save-etag"', $log); - $this->assertStringContainsString('"op":"save-value"', $log); - $this->assertStringContainsString('"op":"save-donut-view"', $log); - $this->assertStringContainsString('"op":"save-donut"', $log); - $this->assertStringContainsString('"op":"found-donut-view"', $log); + + // The rendered page is served from cache on the second access: the GET scope + // closes as a hit and the whole tree validates against the context schemas. + $tree = $this->flushAndValidate($this->logger); + $types = self::collectTypes($tree); + $this->assertContains('get', $types); + $this->assertContains('cache_hit', $types); + $this->assertArrayHasKey('Age', $blogPosting->headers); $this->assertArrayHasKey(Header::CDN_CACHE_CONTROL, $blogPosting->headers); } diff --git a/tests/Fake/FakeErrorCache.php b/tests/Fake/FakeErrorCache.php index 13b0efa8..26ca5c3c 100644 --- a/tests/Fake/FakeErrorCache.php +++ b/tests/Fake/FakeErrorCache.php @@ -14,12 +14,12 @@ class FakeErrorCache implements AdapterInterface { public function getItem($key): CacheItem { - throw new RuntimeException(); + throw new RuntimeException('cache server down'); } public function getItems(array $keys = []): iterable { - return []; + throw new RuntimeException('cache server down'); } public function hasItem($key): bool diff --git a/tests/Fake/fake-app/src/Resource/Page/Dep/LevelThree.php b/tests/Fake/fake-app/src/Resource/Page/Dep/LevelThree.php index 3bf5b7cf..4fe0ae7a 100644 --- a/tests/Fake/fake-app/src/Resource/Page/Dep/LevelThree.php +++ b/tests/Fake/fake-app/src/Resource/Page/Dep/LevelThree.php @@ -3,6 +3,7 @@ namespace FakeVendor\HelloWorld\Resource\Page\Dep; use BEAR\RepositoryModule\Annotation\Cacheable; +use BEAR\RepositoryModule\Annotation\Purge; use BEAR\Resource\Annotation\Embed; use BEAR\Resource\ResourceObject; @@ -15,4 +16,13 @@ public function onGet() { return $this; } + + // A write busts this leaf's cache; the surrogate-key cascade invalidates + // its dependents (level-two, level-one) — the command-driven invalidation + // demonstrated in demo/run-dependency.php. + #[Purge(uri: 'page://self/dep/level-three')] + public function onPut() + { + return $this; + } } diff --git a/tests/Fake/fake-app/src/Resource/Page/Html/SelfEtag.php b/tests/Fake/fake-app/src/Resource/Page/Html/SelfEtag.php new file mode 100644 index 00000000..6221d232 --- /dev/null +++ b/tests/Fake/fake-app/src/Resource/Page/Html/SelfEtag.php @@ -0,0 +1,25 @@ +body = [ + 'article' => '1', + ]; + $this->headers[Header::ETAG] = '"self-etag"'; + + return $this; + } +} diff --git a/tests/FakeThrowingPurger.php b/tests/FakeThrowingPurger.php new file mode 100644 index 00000000..73091d89 --- /dev/null +++ b/tests/FakeThrowingPurger.php @@ -0,0 +1,21 @@ +override(new class extends AbstractModule { + protected function configure(): void + { + $this->bind(SemanticLoggerInterface::class)->toInstance( + new SafeSemanticLogger(new ThrowingSemanticLogger()), + ); + } + }); + $injector = new Injector($module, __DIR__ . '/tmp'); + $resource = $injector->getInstance(ResourceInterface::class); + + // Building the 3-level dependency chain must succeed despite the failing logger. + $ro = $resource->get('page://self/dep/level-one'); + $this->assertSame(200, $ro->code); + $this->assertArrayHasKey(Header::ETAG, $ro->headers); + $this->assertArrayNotHasKey(Header::AGE, $ro->headers, 'first access is a miss (no Age header)'); + + // A second access is served from cache: same stored ETag, an Age header proves the + // stored entry was reused, and still no exception leaks out. + $cached = $resource->get('page://self/dep/level-one'); + $this->assertSame($ro->headers[Header::ETAG], $cached->headers[Header::ETAG]); + $this->assertArrayHasKey(Header::AGE, $cached->headers, 'second access is an observable cache hit'); + } + + public function testCacheErrorIsLoggedWhenCacheServerIsDown(): void + { + $module = new FakeEtagPoolModule(ModuleFactory::getInstance('FakeVendor\HelloWorld')); + $module->override(new class extends AbstractModule { + protected function configure(): void + { + $this->bind(TagAwareAdapterInterface::class)->annotatedWith(ResourceObjectPool::class)->toInstance(new TagAwareAdapter(new FakeErrorCache())); + } + }); + $injector = new Injector($module, __DIR__ . '/tmp'); + $resource = $injector->getInstance(ResourceInterface::class); + $logger = $injector->getInstance(SemanticLoggerInterface::class); + + // The cache pool is down: the read falls back to a live GET with a warning, not an exception. + $warningCaught = false; + set_error_handler(static function (int $errno) use (&$warningCaught): bool { + if ($errno === E_USER_WARNING) { + $warningCaught = true; + + return true; // swallow the cache-down warning + } + + return false; + }); + try { + $ro = $resource->get('app://self/user', ['id' => 1]); + } finally { + restore_error_handler(); + } + + $this->assertTrue($warningCaught, 'the cache-down fallback warns (E_USER_WARNING) instead of throwing'); + $this->assertSame(200, $ro->code); + + $tree = $this->flushAndValidate($logger); + // The outage is logged as cache_error, distinguishable from a cold miss... + $error = self::eventContextJsonOf($tree, 'cache_error'); + $this->assertNotNull($error, 'a cache_error event marks the degraded cache layer'); + $this->assertStringContainsString('app://self/user', $error); + $this->assertStringContainsString('"operation":"read"', $error, 'the failing side (the repository get) is recorded'); + $this->assertStringContainsString('cache server down', $error); + // ...while the get scope still closes cache_miss: the pair (cache_error + cache_miss) + // is an outage, a lone cache_miss is a cold cache. + $close = self::closeContextJsonOf($tree, 'cache_miss'); + $this->assertNotNull($close, 'the get scope still closes cache_miss'); + $this->assertStringContainsString('"layer":"resource"', $close); + } +} diff --git a/tests/QueryRepositoryTest.php b/tests/QueryRepositoryTest.php index 3b13d7df..4be4d111 100644 --- a/tests/QueryRepositoryTest.php +++ b/tests/QueryRepositoryTest.php @@ -11,9 +11,11 @@ use BEAR\Resource\ResourceInterface; use BEAR\Resource\Uri; use BEAR\Sunday\Extension\Transfer\HttpCacheInterface; +use FakeVendor\HelloWorld\Resource\App\ControlExpiry; use FakeVendor\HelloWorld\Resource\App\NullView; use FakeVendor\HelloWorld\Resource\App\User\Profile; use FakeVendor\HelloWorld\Resource\Page\None; +use Koriym\SemanticLogger\SemanticLoggerInterface; use PHPUnit\Framework\TestCase; use Psr\Cache\CacheItemPoolInterface; use Ray\Di\AbstractModule; @@ -35,10 +37,12 @@ class QueryRepositoryTest extends TestCase { + use SemanticLogTreeTrait; + private ResourceInterface $resource; private QueryRepositoryInterface $repository; private HttpCacheInterface $httpCache; - private RepositoryLoggerInterface $logger; + private SemanticLoggerInterface $logger; protected function setUp(): void { @@ -47,16 +51,15 @@ protected function setUp(): void $this->repository = $injector->getInstance(QueryRepositoryInterface::class); $this->resource = $injector->getInstance(ResourceInterface::class); $this->httpCache = $injector->getInstance(HttpCacheInterface::class); - $this->logger = $injector->getInstance(RepositoryLoggerInterface::class); + $this->logger = $injector->getInstance(SemanticLoggerInterface::class); parent::setUp(); } protected function tearDown(): void { - $log = ((string) $this->logger); - // error_log((string) $log); // uncomment to see the debug log - unset($log); + // Every emitted log entry must conform to the published schema (drift detection) + $this->flushAndValidate($this->logger); } public function testPurgeSameResourceObjectByPatch(): void @@ -104,6 +107,21 @@ public function testNoAnnotationLifeTime(): void $this->assertTrue($result); } + public function testPastExpiryAtIsClampedToZeroTtl(): void + { + // A past expiryAt means "already expired": the TTL clamps to 0 instead of going + // negative (the save_* schemas declare "minimum": 0). + $ro = new ControlExpiry(); + $ro->uri = new Uri('app://self/control-expiry'); + $ro->body = ['expiry_at' => '2000-01-01 00:00:00']; + $this->repository->put($ro); + $tree = $this->flushAndValidate($this->logger); + + $saveValue = self::eventContextJsonOf($tree, 'save_value'); + $this->assertNotNull($saveValue); + $this->assertStringContainsString('"ttl":0', $saveValue); + } + public function testPutResquestEmbeddedResoureView(): void { $uri = 'page://self/emb-view'; @@ -113,6 +131,13 @@ public function testPutResquestEmbeddedResoureView(): void assert($state instanceof ResourceState); assert(is_array($state->body)); $this->assertSame(1, $state->body['num']); + + // save_view records its invalidation tags, including the resource's own URI tag + $tree = $this->flushAndValidate($this->logger); + $saveView = self::eventContextJsonOf($tree, 'save_view'); + $this->assertNotNull($saveView); + $this->assertStringContainsString('"_emb-view_"', $saveView); + $expected = '{ "time": { "none": "none" diff --git a/tests/RecordingSemanticLogger.php b/tests/RecordingSemanticLogger.php new file mode 100644 index 00000000..129004b8 --- /dev/null +++ b/tests/RecordingSemanticLogger.php @@ -0,0 +1,60 @@ + */ + public array $opens = []; + + /** @var list */ + public array $events = []; + + /** @var list */ + public array $closes = []; + + #[Override] + public function open(AbstractContext $context): string + { + $this->opens[] = $context; + + return (string) count($this->opens); + } + + #[Override] + public function event(AbstractContext $context): void + { + $this->events[] = $context; + } + + #[Override] + public function close(AbstractContext $context, string $openId): void + { + $this->closes[] = $context; + } + + /** {@inheritDoc} */ + #[Override] + public function flush(array $links = []): LogJson + { + return new LogJson(self::SEMANTIC_LOG_SCHEMA_URL, [], [], [], $links); + } +} diff --git a/tests/RepositoryLoggerTest.php b/tests/RepositoryLoggerTest.php index 69082b7f..783b7d24 100644 --- a/tests/RepositoryLoggerTest.php +++ b/tests/RepositoryLoggerTest.php @@ -86,4 +86,45 @@ public function testResetAllowsNewLogs(): void $this->assertSame('{"op":"new-operation"}', (string) $logger); } + + public function testGetLogsReturnsMergedEntriesInOrder(): void + { + $logger = new RepositoryLogger(); + $logger->log('cache-miss', ['uri' => 'page://self/user', 'layer' => 'resource']); + $logger->log('depends-on', ['parent' => 'page://self/user', 'child' => 'app://self/profile', 'childTags' => ['_profile_']]); + + $this->assertSame([ + ['op' => 'cache-miss', 'uri' => 'page://self/user', 'layer' => 'resource'], + ['op' => 'depends-on', 'parent' => 'page://self/user', 'child' => 'app://self/profile', 'childTags' => ['_profile_']], + ], $logger->getLogs()); + } + + public function testGetOpsReturnsOperationSequence(): void + { + $logger = new RepositoryLogger(); + $logger->log('cache-miss', ['uri' => 'page://self/user', 'layer' => 'resource']); + $logger->log('put-query-repository', ['uri' => 'page://self/user']); + $logger->log('cache-hit', ['uri' => 'page://self/user', 'layer' => 'resource']); + + $this->assertSame(['cache-miss', 'put-query-repository', 'cache-hit'], $logger->getOps()); + } + + public function testResetClearsStructuredAccessors(): void + { + $logger = new RepositoryLogger(); + $logger->log('cache-hit', ['uri' => 'page://self/user', 'layer' => 'resource']); + $logger->reset(); + + $this->assertSame([], $logger->getLogs()); + $this->assertSame([], $logger->getOps()); + } + + public function testNullRepositoryLoggerIsNoOp(): void + { + $logger = new NullRepositoryLogger(); + $logger->log('cache-hit', ['uri' => 'page://self/user', 'layer' => 'resource']); + $logger->reset(); + + $this->assertSame('', (string) $logger); + } } diff --git a/tests/ResourceRepositoryTest.php b/tests/ResourceRepositoryTest.php index 334a4a81..a445f52f 100644 --- a/tests/ResourceRepositoryTest.php +++ b/tests/ResourceRepositoryTest.php @@ -4,6 +4,7 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\NullSemanticLogger; use BEAR\QueryRepository\QueryRepository as Repository; use BEAR\Resource\Uri; use FakeVendor\HelloWorld\Resource\Page\Index; @@ -37,10 +38,10 @@ public function get() } }; $this->repository = new Repository( - new RepositoryLogger(), + new NullSemanticLogger(), new HeaderSetter(new EtagSetter()), new ResourceStorage( - new RepositoryLogger(), + new NullSemanticLogger(), new NullPurger(), new UriTag(), new ResourceStorageSaver(), @@ -105,10 +106,10 @@ public function get() } }; $repository = new Repository( - new RepositoryLogger(), + new NullSemanticLogger(), new HeaderSetter(new EtagSetter()), new ResourceStorage( - new RepositoryLogger(), + new NullSemanticLogger(), new NullPurger(), new UriTag(), new ResourceStorageSaver(), diff --git a/tests/ResourceStorageTest.php b/tests/ResourceStorageTest.php index 17009540..28a4c876 100644 --- a/tests/ResourceStorageTest.php +++ b/tests/ResourceStorageTest.php @@ -4,19 +4,29 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\Context\InvalidateContext; +use BEAR\QueryRepository\Log\Context\SaveDonutContext; +use BEAR\QueryRepository\Log\Context\SaveValueContext; +use BEAR\QueryRepository\Log\NullSemanticLogger; use BEAR\Resource\Uri; use FakeVendor\HelloWorld\Resource\Page\Index; +use Koriym\SemanticLogger\SemanticLoggerInterface; +use Override; use PHPUnit\Framework\TestCase; use Ray\Di\ProviderInterface; +use RuntimeException; +use Symfony\Component\Cache\Adapter\ArrayAdapter; use Symfony\Component\Cache\Adapter\FilesystemAdapter; use Symfony\Component\Cache\Adapter\TagAwareAdapter; +use function assert; + class ResourceStorageTest extends TestCase { private ResourceStorage $storage; private Index $ro; - public static function getResourceStorageInstance(): ResourceStorage + public static function getResourceStorageInstance(SemanticLoggerInterface|null $logger = null, PurgerInterface|null $purger = null): ResourceStorage { $tagAwareAdapter = new TagAwareAdapter(new FilesystemAdapter('', 0, __DIR__ . '/tmp')); $tagAwareAdapterProvider = new class ($tagAwareAdapter) implements ProviderInterface{ @@ -31,8 +41,8 @@ public function get() }; return new ResourceStorage( - new RepositoryLogger(), - new NullPurger(), + $logger ?? new NullSemanticLogger(), + $purger ?? new NullPurger(), new UriTag(), new ResourceStorageSaver(), new GlobalServerContext(), @@ -57,6 +67,71 @@ public function testSaveGetStatic(): void $this->assertInstanceOf(ResourceDonut::class, $donut); } + public function testInvalidateTagsWithNullPurgerLogsCdnSkipped(): void + { + $logger = new RecordingSemanticLogger(); + $storage = self::getResourceStorageInstance($logger); + + $storage->invalidateTags(['_user_']); + + $context = $logger->events[0]; + assert($context instanceof InvalidateContext); + $this->assertTrue($context->roPoolInvalidated); + $this->assertTrue($context->etagPoolInvalidated); + // The default NullPurger is a no-op: the CDN side is "skipped", not "purged" — + // nothing was purged, but nothing was meant to be. + $this->assertSame('skipped', $context->cdnStatus); + $this->assertSame('skipped', $context->jsonSerialize()['cdn']); + $this->assertGreaterThanOrEqual(0, $context->durationMs); + } + + public function testInvalidateTagsLogsCdnPurgedWithConfiguredPurger(): void + { + $logger = new RecordingSemanticLogger(); + $purger = new class implements PurgerInterface { + /** @var list */ + public array $tags = []; + + #[Override] + public function __invoke(string $tag): void + { + $this->tags[] = $tag; + } + }; + $storage = self::getResourceStorageInstance($logger, $purger); + + $storage->invalidateTags(['_user_']); + + $this->assertSame(['_user_'], $purger->tags, 'the configured purger received the surrogate keys'); + $context = $logger->events[0]; + assert($context instanceof InvalidateContext); + $this->assertSame('purged', $context->cdnStatus, 'a real purger that ran without error logs "purged"'); + $this->assertSame('purged', $context->jsonSerialize()['cdn']); + } + + public function testInvalidateTagsFailsClosedWhenPurgerFails(): void + { + $logger = new RecordingSemanticLogger(); + $storage = self::getResourceStorageInstance($logger, new FakeThrowingPurger()); + + // The CDN purge is fail-closed: a purge failure propagates so the write does not + // silently leave stale CDN content. The local pools are invalidated first and the + // outcome is logged as cdn=failed before the exception surfaces. + try { + $storage->invalidateTags(['_user_']); + $this->fail('Expected the purger failure to propagate (fail-closed)'); + } catch (RuntimeException $e) { + $this->assertStringContainsString('purge failed', $e->getMessage()); + } + + $context = $logger->events[0]; + assert($context instanceof InvalidateContext); + $this->assertTrue($context->roPoolInvalidated); + $this->assertTrue($context->etagPoolInvalidated); + $this->assertSame('failed', $context->cdnStatus); + $this->assertSame('failed', $context->jsonSerialize()['cdn']); + } + public function testHasEtagAcceptsIfNoneMatchVariants(): void { $this->storage->saveEtag($this->ro->uri, '"123456"', '', 10); @@ -106,4 +181,98 @@ public function testEtagIsNotRegisteredAsInvalidationTag(): void $this->storage->invalidateTags([(new UriTag())($this->ro->uri)]); $this->assertNull($this->storage->get($this->ro->uri)); } + + public function testSaveValueLogsSavedFalseWhenPoolRejectsEntry(): void + { + // ResourceStorageSaver is final, so the failure is induced one layer down: an inner + // pool whose commit() rejects every entry (e.g. storage full). + $failingPool = new TagAwareAdapter(new class extends ArrayAdapter { + #[Override] + public function commit(): bool + { + return false; + } + }); + $poolProvider = new class ($failingPool) implements ProviderInterface{ + public function __construct(private readonly TagAwareAdapter $tagAwareAdapter) + { + } + + public function get() + { + return $this->tagAwareAdapter; + } + }; + $logger = new RecordingSemanticLogger(); + $storage = new ResourceStorage( + $logger, + new NullPurger(), + new UriTag(), + new ResourceStorageSaver(), + new GlobalServerContext(), + $poolProvider, + $poolProvider, + ); + + $saved = $storage->saveValue($this->ro, 10); + + $this->assertFalse($saved, 'the store result surfaces to the caller'); + $context = $logger->events[0]; + assert($context instanceof SaveValueContext); + $this->assertFalse($context->saved, 'the log records that the entry is NOT cached despite the save event'); + $this->assertSame(10, $context->ttl); + } + + public function testSaveDonutLogsSavedFalseWhenPoolRejectsEntry(): void + { + // Same failure injection as the saveValue case above: an inner pool whose + // commit() rejects every entry. The round-2 assert removal made saved:false + // observable for donut stores; this pins it. + $failingPool = new TagAwareAdapter(new class extends ArrayAdapter { + #[Override] + public function commit(): bool + { + return false; + } + }); + $poolProvider = new class ($failingPool) implements ProviderInterface{ + public function __construct(private readonly TagAwareAdapter $tagAwareAdapter) + { + } + + public function get() + { + return $this->tagAwareAdapter; + } + }; + $logger = new RecordingSemanticLogger(); + $storage = new ResourceStorage( + $logger, + new NullPurger(), + new UriTag(), + new ResourceStorageSaver(), + new GlobalServerContext(), + $poolProvider, + $poolProvider, + ); + $donut = ResourceDonut::create($this->ro, new DonutRenderer(), new SurrogateKeys(new Uri('app://self/')), null, false); + + $storage->saveDonut($this->ro->uri, $donut, null, []); + + $context = $logger->events[0]; + assert($context instanceof SaveDonutContext); + $this->assertFalse($context->saved, 'the log records that the donut entry is NOT cached despite the save event'); + } + + public function testSaveValueClampsNegativeTtlToZero(): void + { + $logger = new RecordingSemanticLogger(); + $storage = self::getResourceStorageInstance($logger); + + $storage->saveValue($this->ro, -10); + + $context = $logger->events[0]; + assert($context instanceof SaveValueContext); + $this->assertSame(0, $context->ttl, 'a negative ttl is clamped to 0 (the schemas declare "minimum": 0)'); + } } diff --git a/tests/SafeSemanticLoggerTest.php b/tests/SafeSemanticLoggerTest.php new file mode 100644 index 00000000..84215a18 --- /dev/null +++ b/tests/SafeSemanticLoggerTest.php @@ -0,0 +1,161 @@ +open(new GetContext('page://self/x')); + $safe->close(new CacheMissContext('resource'), $id); + // The delegate throws on flush; the failure is swallowed and the wiped session + // is marked with a log_session_broken sentinel instead of vanishing silently. + $opens = $safe->flush()->toArray()['open']; + $this->assertCount(1, $opens); + $this->assertSame('log_session_broken', $opens[0]['type']); + $this->assertSame('flush failed', $opens[0]['context']['reason']); + + // Recovery: the next session uses a fresh delegate and logs normally. + $id2 = $safe->open(new GetContext('page://self/y')); + $safe->close(new CacheHitContext('resource'), $id2); + $this->assertCount(1, $safe->flush()->toArray()['open']); + } + + public function testSerializesWithoutCarryingSessionState(): void + { + $safe = new SafeSemanticLogger(new SemanticLogger()); + $safe->open(new GetContext('page://self/x')); // leave a session open (dirty) + + $restored = unserialize(serialize($safe)); + $this->assertInstanceOf(SafeSemanticLogger::class, $restored); + + // The restored logger is a fresh session, not the dirty one. + $id = $restored->open(new GetContext('page://self/z')); + $restored->close(new CacheMissContext('resource'), $id); + $this->assertCount(1, $restored->flush()->toArray()['open']); + } + + public function testLifoViolationBreaksSessionThenFlushRecovers(): void + { + // Pin the failure chain against a REAL SemanticLogger delegate (no fake): + // closing scope A while B is still open violates LIFO order. + $safe = new SafeSemanticLogger(new SemanticLogger()); + + $idA = $safe->open(new GetContext('page://self/a')); + $safe->open(new GetContext('page://self/b')); + // The delegate throws InvalidOperationOrderException; SafeSemanticLogger swallows + // it and marks the session broken. + $safe->close(new CacheMissContext('resource'), $idA); + // The broken (still-unclosed) session cannot flush; the wipe is marked with a + // log_session_broken sentinel carrying the cause, not returned as an empty log. + $opens = $safe->flush()->toArray()['open']; + $this->assertCount(1, $opens); + $this->assertSame('log_session_broken', $opens[0]['type']); + $this->assertNotSame('', $opens[0]['context']['reason']); + + // Recovery: flush() replaced the dirty delegate, so the next session logs normally. + $id = $safe->open(new GetContext('page://self/c')); + $safe->close(new CacheHitContext('resource'), $id); + $this->assertCount(1, $safe->flush()->toArray()['open']); + } + + public function testEventFailureIsSwallowed(): void + { + // Delegate succeeds on open() (so SafeSemanticLogger stays unbroken and enters + // event()'s try) but throws on event(): the failure must be swallowed. + $flaky = new class implements SemanticLoggerInterface { + public function open(AbstractContext $context): string + { + return 'x'; + } + + public function event(AbstractContext $context): void + { + throw new RuntimeException('event failed'); + } + + public function close(AbstractContext $context, string $openId): void + { + } + + public function flush(array $links = []): LogJson + { + return new LogJson('https://koriym.github.io/Koriym.SemanticLogger/schemas/semantic-log.json', [], [], [], $links); + } + }; + $safe = new SafeSemanticLogger($flaky); + + $safe->open(new GetContext('page://self/x')); + $safe->event(new CacheMissContext('resource')); // throws inside; must not escape + // The session is marked broken and flush() returns an empty log without throwing. + $this->assertSame([], $safe->flush()->toArray()['open']); + } + + public function testCloseFailureIsSwallowed(): void + { + // Delegate succeeds on open() but throws on close(): the failure must be swallowed. + $flaky = new class implements SemanticLoggerInterface { + public function open(AbstractContext $context): string + { + return 'x'; + } + + public function event(AbstractContext $context): void + { + } + + public function close(AbstractContext $context, string $openId): void + { + throw new RuntimeException('close failed'); + } + + public function flush(array $links = []): LogJson + { + return new LogJson('https://koriym.github.io/Koriym.SemanticLogger/schemas/semantic-log.json', [], [], [], $links); + } + }; + $safe = new SafeSemanticLogger($flaky); + + $id = $safe->open(new GetContext('page://self/x')); + $safe->close(new CacheMissContext('resource'), $id); // throws inside; must not escape + $this->assertSame([], $safe->flush()->toArray()['open']); + } +} diff --git a/tests/SemanticLogSchemaTest.php b/tests/SemanticLogSchemaTest.php new file mode 100644 index 00000000..6f21f423 --- /dev/null +++ b/tests/SemanticLogSchemaTest.php @@ -0,0 +1,252 @@ +resource = $injector->getInstance(ResourceInterface::class); + $this->logger = $injector->getInstance(SemanticLoggerInterface::class); + $this->repository = $injector->getInstance(QueryRepositoryInterface::class); + $this->storage = $injector->getInstance(ResourceStorageInterface::class); + + parent::setUp(); + } + + public function testDependencyChainValidatesAndNestsAsEmbedTree(): void + { + $this->resource->get('page://self/dep/level-one'); + $tree = $this->flushAndValidate($this->logger); + + // The embed structure is the log structure: one -> two -> three nested opens. + $this->assertGreaterThanOrEqual(3, self::maxOpenDepth($tree)); + + // Lifecycle and dependency facts are present and schema-valid. + $types = self::collectTypes($tree); + foreach (['get', 'cache_miss', 'depends_on', 'invalidate', 'save_value', 'save_etag'] as $type) { + $this->assertContains($type, $types); + } + } + + public function testCommandScopeRecordsCausality(): void + { + // User::onPut carries #[Purge] and #[Refresh]; the command scope records them. + $this->resource->put('app://self/user', ['id' => 1, 'name' => 'bear', 'age' => 10]); + $tree = $this->flushAndValidate($this->logger); + + $commandContext = self::contextJsonOf($tree, 'command'); + $this->assertNotNull($commandContext, 'a command scope is opened'); + $this->assertStringContainsString('"method":"onPut"', $commandContext); + $this->assertStringContainsString('Refresh', $commandContext); + $this->assertStringContainsString('Purge', $commandContext); + $this->assertStringContainsString('"source":"CommandInterceptor"', $commandContext); + + $types = self::collectTypes($tree); + $this->assertContains('purge', $types, 'the #[Purge]/#[Refresh] invalidations nest under the command scope'); + $this->assertContains('command_result', $types, 'the scope close records the command outcome'); + } + + public function testFailedCommandRecordsScopeWithNoInvalidationEvents(): void + { + // User::onPatch with an empty name returns 400. A failed write must still open a + // command scope — closed with the 4xx result and no invalidation events — so the + // log shows the purge/refresh was correctly skipped rather than silently absent. + $this->resource->patch('app://self/user', ['id' => 1, 'name' => '']); + $tree = $this->flushAndValidate($this->logger); + + $commandContext = self::contextJsonOf($tree, 'command'); + $this->assertNotNull($commandContext, 'a failed write still opens a command scope'); + $this->assertStringContainsString('"method":"onPatch"', $commandContext); + $close = self::closeContextJsonOf($tree, 'command_result'); + $this->assertNotNull($close); + $this->assertStringContainsString('"code":400', $close); + + $types = self::collectTypes($tree); + $this->assertNotContains('purge', $types, 'no purge on a failed write'); + $this->assertNotContains('invalidate', $types, 'no invalidation on a failed write'); + } + + public function testNon200GetLogsPutSkippedWithActualCode(): void + { + // Code::onGet returns 203. A non-200 GET is purged, not stored; the log must + // record the actual code — without it a 203 and a 404 are indistinguishable. + $this->resource->get('app://self/code'); + $tree = $this->flushAndValidate($this->logger); + + $putSkipped = self::eventContextJsonOf($tree, 'put_skipped'); + $this->assertNotNull($putSkipped, 'the skipped put is recorded'); + $this->assertStringContainsString('"reason":"error-code"', $putSkipped); + $this->assertStringContainsString('"code":203', $putSkipped, 'the actual response code is recorded'); + + $types = self::collectTypes($tree); + $this->assertContains('purge', $types, 'a non-200 response is purged instead of stored'); + } + + public function testSecondGetClosesWithResourceLayerCacheHit(): void + { + // First GET is a cold miss and populates the cache; drain its session. + $this->resource->get('app://self/user', ['id' => 1]); + $this->logger->flush(); + + // Second GET must close the get scope with a resource-layer cache_hit — + // the resource layer had no cache_hit pin (only the donut layers did). + $this->resource->get('app://self/user', ['id' => 1]); + $tree = $this->flushAndValidate($this->logger); + + $close = self::closeContextJsonOf($tree, 'cache_hit'); + $this->assertNotNull($close, 'the second GET is served from cache'); + $this->assertStringContainsString('"layer":"resource"', $close); + } + + public function testTopLevelPutIsRootedInManualStoreScope(): void + { + // A direct put() has no enclosing AOP scope, so it must root its save events under a + // manual_store scope; otherwise SemanticLogger drops the event-only session at flush. + $ro = new None(); + $ro->uri = new Uri('page://self/none'); + $this->repository->put($ro); + $tree = $this->flushAndValidate($this->logger); + + $types = self::collectTypes($tree); + $this->assertContains('manual_store', $types, 'a manual_store scope roots the direct put'); + $this->assertContains('manual_store_result', $types, 'the scope close records the store outcome'); + $this->assertContains('save_value', $types, 'the save event nests under the manual_store scope'); + } + + public function testTopLevelInvalidateIsRootedInManualInvalidateScope(): void + { + // A direct invalidateTags() has no enclosing AOP scope, so it must root its outcome + // under a manual_invalidate scope to stay visible in the flushed log. + $this->storage->invalidateTags(['_test_tag_']); + $tree = $this->flushAndValidate($this->logger); + + $types = self::collectTypes($tree); + $this->assertContains('manual_invalidate', $types, 'a manual_invalidate scope roots the direct invalidation'); + $this->assertContains('invalidate', $types, 'the scope close records the invalidation outcome'); + } + + public function testTopLevelPurgeIsRootedInManualPurgeScope(): void + { + // A direct purge() has no enclosing AOP scope, so it must root its invalidation + // under a manual_purge scope to stay visible in the flushed log. + $this->repository->purge(new Uri('page://self/user')); + $tree = $this->flushAndValidate($this->logger); + + $types = self::collectTypes($tree); + $this->assertContains('manual_purge', $types, 'a manual_purge scope roots the direct purge'); + $this->assertContains('invalidate', $types, 'the invalidation nests under the manual_purge scope'); + $this->assertContains('manual_purge_result', $types, 'the scope close records the purge outcome'); + } + + public function testTopLevelPurgeLogsFailClosedOutcomeWhenPurgerFails(): void + { + $module = new FakeEtagPoolModule(ModuleFactory::getInstance('FakeVendor\HelloWorld')); + $module->override(new class extends AbstractModule { + protected function configure(): void + { + $this->bind(PurgerInterface::class)->toInstance(new FakeThrowingPurger()); + } + }); + $injector = new Injector($module, __DIR__ . '/tmp'); + $repository = $injector->getInstance(QueryRepositoryInterface::class); + $logger = $injector->getInstance(SemanticLoggerInterface::class); + + // The CDN purge is fail-closed: the exception propagates through purge()'s try/finally. + try { + $repository->purge(new Uri('page://self/user')); + $this->fail('Expected the purger failure to propagate (fail-closed)'); + } catch (RuntimeException $e) { + $this->assertStringContainsString('purge failed', $e->getMessage()); + } + + // The flushed tree is still well-formed: the manual_purge scope is closed with the + // failed outcome, and the nested invalidate event records cdn=failed. + $tree = $this->flushAndValidate($logger); + $invalidate = self::eventContextJsonOf($tree, 'invalidate'); + $this->assertNotNull($invalidate); + $this->assertStringContainsString('"cdn":"failed"', $invalidate); + $close = self::closeContextJsonOf($tree, 'manual_purge_result'); + $this->assertNotNull($close); + $this->assertStringContainsString('"result":"failed"', $close); + } + + public function testValidatorRejectsContextViolatingItsSchema(): void + { + // cache_hit context without the required "layer" must be rejected. + $tree = [ + '$schema' => 'https://koriym.github.io/Koriym.SemanticLogger/schemas/semantic-log.json', + 'open' => [ + [ + 'id' => 'get_1', + 'type' => 'get', + 'schemaUrl' => 'https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/get.json', + 'context' => ['uri' => 'page://self/x'], + 'close' => [ + 'id' => 'cache_hit_1', + 'type' => 'cache_hit', + 'schemaUrl' => 'https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/cache_hit.json', + // an empty object (not []) so the rejection comes from the JSON-schema + // layer, not the validator's structural guard + 'context' => (object) [], // missing "layer" + ], + ], + ], + ]; + $file = (string) tempnam(sys_get_temp_dir(), 'slog'); + file_put_contents($file, (string) json_encode($tree, JSON_UNESCAPED_SLASHES)); + + $exception = null; + ob_start(); + try { + (new SemanticLogValidator())->validate($file, dirname(__DIR__) . '/docs/schemas/context'); + } catch (RuntimeException $e) { + $exception = $e; + } finally { + $output = (string) ob_get_clean(); + unlink($file); + } + + $this->assertInstanceOf(RuntimeException::class, $exception, 'a schema-violating context must be rejected'); + // The schema layer names the failing type; the structural guard never does. + $this->assertStringContainsString('(cache_hit)', $output, 'the rejection must come from schema validation'); + } +} diff --git a/tests/SemanticLogTreeTrait.php b/tests/SemanticLogTreeTrait.php new file mode 100644 index 00000000..348c6168 --- /dev/null +++ b/tests/SemanticLogTreeTrait.php @@ -0,0 +1,280 @@ + the flushed log tree, for further assertions + */ + private function flushAndValidate(SemanticLoggerInterface $logger): array + { + /** @var array $tree */ + $tree = $logger->flush()->toArray(); + $open = $tree['open'] ?? []; + if (! is_array($open) || $open === []) { + return $tree; // nothing was logged in this scenario; nothing to validate + } + + $file = (string) tempnam(sys_get_temp_dir(), 'slog'); + file_put_contents($file, (string) json_encode($tree, JSON_UNESCAPED_SLASHES)); + $schemaDir = dirname(__DIR__) . '/docs/schemas/context'; + + ob_start(); + try { + (new SemanticLogValidator())->validate($file, $schemaDir); + } finally { + ob_get_clean(); + unlink($file); + } + + return $tree; + } + + /** + * Collect the `type` of every node (open, events, close) in the tree, depth-first + * + * @param array $tree + * + * @return list + */ + private static function collectTypes(array $tree): array + { + $types = []; + self::walk($tree['open'] ?? [], $types); + self::walkEvents($tree['events'] ?? [], $types); + + return $types; + } + + /** + * Maximum nesting depth of open scopes (a chain of N nested opens returns N) + * + * @param array $tree + */ + private static function maxOpenDepth(array $tree): int + { + return self::depth($tree['open'] ?? []); + } + + /** + * JSON of the first node's context whose type matches, or null if absent + * + * Note: only descends `open` scopes; it does not match types that live under + * `events` or a `close`. Sufficient for open-scope types such as `command`. + * + * @param array $tree + */ + private static function contextJsonOf(array $tree, string $type): string|null + { + return self::findContextJson($tree['open'] ?? [], $type); + } + + /** + * JSON of the first event context whose type matches, or null if absent + * + * Searches events nested under `open` scopes and top-level events alike. + * + * @param array $tree + */ + private static function eventContextJsonOf(array $tree, string $type): string|null + { + $found = self::findEventContextJson($tree['open'] ?? [], $type); + if ($found !== null) { + return $found; + } + + $events = $tree['events'] ?? []; + if (! is_array($events)) { + return null; + } + + foreach ($events as $event) { + if (is_array($event) && ($event['type'] ?? null) === $type) { + return (string) json_encode($event['context'] ?? null, JSON_UNESCAPED_SLASHES); + } + } + + return null; + } + + /** + * JSON of the first close context whose type matches, or null if absent + * + * @param array $tree + */ + private static function closeContextJsonOf(array $tree, string $type): string|null + { + return self::findCloseContextJson($tree['open'] ?? [], $type); + } + + /** + * @param mixed $nodes + * @param list $types + */ + private static function walk(mixed $nodes, array &$types): void + { + if (! is_array($nodes)) { + return; + } + + foreach ($nodes as $node) { + if (! is_array($node)) { + continue; + } + + if (isset($node['type']) && is_string($node['type'])) { + $types[] = $node['type']; + } + + self::walkEvents($node['events'] ?? [], $types); + $close = $node['close'] ?? null; + if (is_array($close) && isset($close['type']) && is_string($close['type'])) { + $types[] = $close['type']; + } + + self::walk($node['open'] ?? [], $types); + } + } + + /** + * @param mixed $events + * @param list $types + */ + private static function walkEvents(mixed $events, array &$types): void + { + if (! is_array($events)) { + return; + } + + foreach ($events as $event) { + if (is_array($event) && isset($event['type']) && is_string($event['type'])) { + $types[] = $event['type']; + } + } + } + + private static function depth(mixed $nodes): int + { + if (! is_array($nodes) || $nodes === []) { + return 0; + } + + $max = 0; + foreach ($nodes as $node) { + if (! is_array($node)) { + continue; + } + + $max = max($max, 1 + self::depth($node['open'] ?? [])); + } + + return $max; + } + + private static function findContextJson(mixed $nodes, string $type): string|null + { + if (! is_array($nodes)) { + return null; + } + + foreach ($nodes as $node) { + if (! is_array($node)) { + continue; + } + + if (($node['type'] ?? null) === $type) { + return (string) json_encode($node['context'] ?? null, JSON_UNESCAPED_SLASHES); + } + + $found = self::findContextJson($node['open'] ?? [], $type); + if ($found !== null) { + return $found; + } + } + + return null; + } + + private static function findEventContextJson(mixed $nodes, string $type): string|null + { + if (! is_array($nodes)) { + return null; + } + + foreach ($nodes as $node) { + if (! is_array($node)) { + continue; + } + + $events = $node['events'] ?? []; + if (is_array($events)) { + foreach ($events as $event) { + if (is_array($event) && ($event['type'] ?? null) === $type) { + return (string) json_encode($event['context'] ?? null, JSON_UNESCAPED_SLASHES); + } + } + } + + $found = self::findEventContextJson($node['open'] ?? [], $type); + if ($found !== null) { + return $found; + } + } + + return null; + } + + private static function findCloseContextJson(mixed $nodes, string $type): string|null + { + if (! is_array($nodes)) { + return null; + } + + foreach ($nodes as $node) { + if (! is_array($node)) { + continue; + } + + $close = $node['close'] ?? null; + if (is_array($close) && ($close['type'] ?? null) === $type) { + return (string) json_encode($close['context'] ?? null, JSON_UNESCAPED_SLASHES); + } + + $found = self::findCloseContextJson($node['open'] ?? [], $type); + if ($found !== null) { + return $found; + } + } + + return null; + } +} diff --git a/tests/ThrowingSemanticLogger.php b/tests/ThrowingSemanticLogger.php new file mode 100644 index 00000000..117881b5 --- /dev/null +++ b/tests/ThrowingSemanticLogger.php @@ -0,0 +1,43 @@ +