diff --git a/CHANGELOG.md b/CHANGELOG.md index 1cb12a37..27926ab7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,22 @@ 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; `NullSemanticLogger` is the zero-cost no-op default. Bound via `SafeSemanticLoggerProvider` in `DonutCacheModule`. +- `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()` and `invalidateTags()` calls are rooted in `manual_store` / `manual_invalidate` scopes so their save/invalidate events stay visible; an event with no enclosing scope would otherwise be dropped at flush. + +### Deprecated +- `RepositoryLogger`, `RepositoryLoggerInterface`, `StructuredRepositoryLoggerInterface`, `NullRepositoryLogger` and `docs/schemas/repository-log.json`. Internal cache code now logs through `Koriym\SemanticLogger\SemanticLoggerInterface`; the legacy flat interface remains bound for BC but receives no internal events. + +### Changed +- Cache logging call sites (`QueryRepository`, `ResourceStorage`, `DonutRepository`, `CacheInterceptor`, `AbstractDonutCacheInterceptor`, `CommandInterceptor`, `RefreshInterceptor`) now emit typed contexts through `SemanticLoggerInterface` instead of `RepositoryLoggerInterface::log()`. +- Added runtime dependency `koriym/semantic-logger`. + ## [1.16.1] - 2026-06-01 ### Fixed 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/run-dependency.php b/demo/run-dependency.php index 62e6ba87..533ac923 100644 --- a/demo/run-dependency.php +++ b/demo/run-dependency.php @@ -18,9 +18,11 @@ 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'; @@ -65,36 +67,26 @@ $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) +$repository->purge(new Uri('page://self/dep/level-three')); // 3. Purge grandchild (cascade) +$resource->get('page://self/dep/level-one'); // 4. Re-access after purge (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. Purge shared child +$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, schema-validated JSON (also: `vendor/bin/stree `) +echo PHP_EOL . "=== Cache Log JSON ===" . PHP_EOL; +echo json_encode($log, JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES) . PHP_EOL; diff --git a/demo/run-donut.php b/demo/run-donut.php index 52f17609..1e965344 100644 --- a/demo/run-donut.php +++ b/demo/run-donut.php @@ -18,11 +18,13 @@ 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; @@ -62,21 +64,14 @@ $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) - -$logger->log('request-start', ['uri' => 'page://self/html/comment', 'method' => 'invalidate']); -$storage->invalidateTags([(new UriTag())(new Uri('page://self/html/comment'))]); // 3. Invalidate comment - -$logger->log('request-start', ['uri' => 'page://self/html/blog-posting']); -$resource->get('page://self/html/blog-posting'); // 4. Access after invalidation - -// Output logs only -echo "=== Cache Log ===" . PHP_EOL; -echo $logger . PHP_EOL; +// Human/AI-readable tree (open = embed scope, close = hit/miss, events = saves/invalidations) +echo "=== Cache Log Tree ===" . PHP_EOL; +echo (new TreeRenderer())->render($logger->flush()->toArray(), new RenderConfig(true, 0.0, 1000, true)) . PHP_EOL; diff --git a/docs/schemas/context/cache_hit.json b/docs/schemas/context/cache_hit.json new file mode 100644 index 00000000..15790213 --- /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.", + "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..205631cd --- /dev/null +++ b/docs/schemas/context/command.json @@ -0,0 +1,36 @@ +{ + "$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" + ], + "properties": { + "method": { + "type": "string" + }, + "annotations": { + "type": "array", + "items": { + "type": "object", + "required": [ + "class", + "uri" + ], + "properties": { + "class": { + "type": "string" + }, + "uri": { + "type": "string" + } + }, + "additionalProperties": false + } + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/command_result.json b/docs/schemas/context/command_result.json new file mode 100644 index 00000000..979cde0c --- /dev/null +++ b/docs/schemas/context/command_result.json @@ -0,0 +1,16 @@ +{ + "$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" + } + }, + "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..785ac1d9 --- /dev/null +++ b/docs/schemas/context/invalidate.json @@ -0,0 +1,43 @@ +{ + "$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.", + "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 best-effort CDN surrogate-key purge", + "type": "string", + "enum": ["purged", "failed"] + }, + "durationMs": { + "description": "Wall-clock duration of the invalidation in milliseconds", + "type": "number", + "minimum": 0 + } + }, + "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..34d33660 --- /dev/null +++ b/docs/schemas/context/manual_store_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_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": { "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..0d334c7b --- /dev/null +++ b/docs/schemas/context/put_donut.json @@ -0,0 +1,32 @@ +{ + "$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": { + "type": [ + "integer", + "null" + ], + "minimum": 0 + }, + "sMaxAge": { + "type": [ + "integer", + "null" + ], + "minimum": 0 + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/refresh_donut.json b/docs/schemas/context/refresh_donut.json new file mode 100644 index 00000000..0af749d0 --- /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 was rebuilt (cache miss path).", + "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..209f2b9e --- /dev/null +++ b/docs/schemas/context/save_donut.json @@ -0,0 +1,24 @@ +{ + "$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", + "sMaxAge" + ], + "properties": { + "uri": { + "type": "string" + }, + "sMaxAge": { + "type": [ + "integer", + "null" + ], + "minimum": 0 + } + }, + "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..8d615579 --- /dev/null +++ b/docs/schemas/context/save_donut_view.json @@ -0,0 +1,31 @@ +{ + "$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", + "surrogateKeys", + "sMaxAge" + ], + "properties": { + "uri": { + "type": "string" + }, + "surrogateKeys": { + "type": "array", + "items": { + "type": "string" + } + }, + "sMaxAge": { + "type": [ + "integer", + "null" + ], + "minimum": 0 + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/save_etag.json b/docs/schemas/context/save_etag.json new file mode 100644 index 00000000..95a25e17 --- /dev/null +++ b/docs/schemas/context/save_etag.json @@ -0,0 +1,27 @@ +{ + "$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 surrogate keys.", + "type": "object", + "required": [ + "uri", + "etag", + "surrogateKeys" + ], + "properties": { + "uri": { + "type": "string" + }, + "etag": { + "type": "string" + }, + "surrogateKeys": { + "type": "array", + "items": { + "type": "string" + } + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/save_value.json b/docs/schemas/context/save_value.json new file mode 100644 index 00000000..922a7175 --- /dev/null +++ b/docs/schemas/context/save_value.json @@ -0,0 +1,31 @@ +{ + "$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" + ], + "properties": { + "uri": { + "type": "string" + }, + "tags": { + "type": "array", + "items": { + "type": "string" + } + }, + "ttl": { + "type": [ + "integer", + "null" + ], + "minimum": 0 + } + }, + "additionalProperties": false +} diff --git a/docs/schemas/context/save_view.json b/docs/schemas/context/save_view.json new file mode 100644 index 00000000..b8452263 --- /dev/null +++ b/docs/schemas/context/save_view.json @@ -0,0 +1,24 @@ +{ + "$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", + "ttl" + ], + "properties": { + "uri": { + "type": "string" + }, + "ttl": { + "type": [ + "integer", + "null" + ], + "minimum": 0 + } + }, + "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..f9260fe1 100644 --- a/src/AbstractDonutCacheInterceptor.php +++ b/src/AbstractDonutCacheInterceptor.php @@ -4,8 +4,13 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\Context\CacheHitContext; +use BEAR\QueryRepository\Log\Context\CacheMissContext; +use BEAR\QueryRepository\Log\Context\GetContext; +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 +28,56 @@ 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 + $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) { + return $ro; + } - /** @var ResourceObject $ro */ - $ro = $invocation->proceed(); - // donut created in ResourceObject - if (isset($ro->headers[Header::ETAG]) || $ro->code >= Code::BAD_REQUEST) { - return $ro; + 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, + ); } - - return static::IS_ENTIRE_CONTENT_CACHEABLE ? // phpcs:ignore - not "self" - $this->donutRepository->putStatic($ro, null, null) : - $this->donutRepository->putDonut($ro, null); } /** @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..c5401200 100644 --- a/src/CacheInterceptor.php +++ b/src/CacheInterceptor.php @@ -5,7 +5,12 @@ namespace BEAR\QueryRepository; use BEAR\QueryRepository\Exception\LogicException; +use BEAR\QueryRepository\Log\Context\CacheHitContext; +use BEAR\QueryRepository\Log\Context\CacheMissContext; +use BEAR\QueryRepository\Log\Context\GetContext; +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 +36,59 @@ { 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) { + $this->triggerWarning($e); - return $invocation->proceed(); // @codeCoverageIgnore - } + return $invocation->proceed(); // @codeCoverageIgnore + } - 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 { + $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 + } - 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..78101da3 --- /dev/null +++ b/src/CommandContextFactory.php @@ -0,0 +1,38 @@ + $invocation */ + public function __invoke(MethodInvocation $invocation): 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); + } +} diff --git a/src/CommandInterceptor.php b/src/CommandInterceptor.php index 03ac15ac..aa1c62bf 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(); } /** @@ -53,8 +60,14 @@ public function invoke(MethodInvocation $invocation) return $ro; } - foreach ($this->commands as $command) { - $command->command($invocation, $ro); + // Open a command scope so the triggered purges/refreshes nest under it. + $openId = $this->logger->open(($this->commandContextFactory)($invocation)); + try { + 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..ff9c2809 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] @@ -46,7 +53,13 @@ public function invoke(MethodInvocation $invocation): ResourceObject return $ro; } - $this->refreshDonutAndState($ro); + // Open a command scope so the donut purge/refresh nests under it (causality). + $openId = $this->logger->open(($this->commandContextFactory)($invocation)); + try { + $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 1401bf1d..919bf204 100644 --- a/src/DonutRepository.php +++ b/src/DonutRepository.php @@ -4,9 +4,14 @@ 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\RefreshDonutContext; use BEAR\Resource\AbstractUri; use BEAR\Resource\ResourceInterface; use BEAR\Resource\ResourceObject; +use Koriym\SemanticLogger\SemanticLoggerInterface; use Override; use function assert; @@ -20,7 +25,7 @@ public function __construct( private ResourceStorageInterface $resourceStorage, private ResourceInterface $resource, private CdnCacheControlHeaderSetterInterface $cdnCacheControlHeaderSetter, - private RepositoryLoggerInterface $logger, + private SemanticLoggerInterface $logger, private DonutRendererInterface $renderer, ) { } @@ -29,9 +34,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; @@ -47,7 +50,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); @@ -69,7 +72,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); @@ -104,14 +107,14 @@ 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) { return $ro; diff --git a/src/Log/Context/CacheHitContext.php b/src/Log/Context/CacheHitContext.php new file mode 100644 index 00000000..4e9c7ec7 --- /dev/null +++ b/src/Log/Context/CacheHitContext.php @@ -0,0 +1,21 @@ + $annotations */ + public function __construct( + public readonly string $method, + public readonly array $annotations, + ) { + } +} 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" (CDN surrogate-key purge) + */ +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 */ + public function __construct( + public readonly array $tags, + public readonly bool $roPoolInvalidated, + public readonly bool $etagPoolInvalidated, + public readonly bool $cdnPurged, + 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->cdnPurged ? 'purged' : 'failed', + 'durationMs' => $this->durationMs, + ]; + } +} diff --git a/src/Log/Context/ManualInvalidateContext.php b/src/Log/Context/ManualInvalidateContext.php new file mode 100644 index 00000000..25f207a7 --- /dev/null +++ b/src/Log/Context/ManualInvalidateContext.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 @@ + $surrogateKeys */ + public function __construct( + public readonly string $uri, + public readonly array $surrogateKeys, + public readonly int|null $sMaxAge, + ) { + } +} diff --git a/src/Log/Context/SaveEtagContext.php b/src/Log/Context/SaveEtagContext.php new file mode 100644 index 00000000..637e2d3a --- /dev/null +++ b/src/Log/Context/SaveEtagContext.php @@ -0,0 +1,24 @@ + $surrogateKeys */ + public function __construct( + public readonly string $uri, + public readonly string $etag, + public readonly array $surrogateKeys, + ) { + } +} diff --git a/src/Log/Context/SaveValueContext.php b/src/Log/Context/SaveValueContext.php new file mode 100644 index 00000000..268d8e07 --- /dev/null +++ b/src/Log/Context/SaveValueContext.php @@ -0,0 +1,24 @@ + $tags */ + public function __construct( + public readonly string $uri, + public readonly array $tags, + public readonly int|null $ttl, + ) { + } +} diff --git a/src/Log/Context/SaveViewContext.php b/src/Log/Context/SaveViewContext.php new file mode 100644 index 00000000..fa0345c9 --- /dev/null +++ b/src/Log/Context/SaveViewContext.php @@ -0,0 +1,22 @@ +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) { + // 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; + + return new LogJson(self::EMPTY_SCHEMA_URL, [], [], [], $links); + } + } + + /** + * 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 +133,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); } diff --git a/src/RefreshInterceptor.php b/src/RefreshInterceptor.php index 14adb17b..2784ef96 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] @@ -41,7 +48,12 @@ public function invoke(MethodInvocation $invocation): ResourceObject } if ($ro->code < Code::BAD_REQUEST) { - $this->command->command($invocation, $ro); + $openId = $this->logger->open(($this->commandContextFactory)($invocation)); + try { + $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 a3d3b1da..9e794c09 100644 --- a/src/ResourceStorage.php +++ b/src/ResourceStorage.php @@ -4,30 +4,42 @@ 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 round; use function sprintf; use function strtoupper; use function trim; /** * @psalm-type Props = array{ - * logger: RepositoryLoggerInterface, + * logger: SemanticLoggerInterface, * purger:PurgerInterface, * uriTag: UriTag, * saver: ResourceStorageSaver, @@ -61,7 +73,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, @@ -137,12 +149,56 @@ 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, + cdnPurged: $purgerError === null, + durationMs: round((hrtime(true) - $start) / 1_000_000, 3), + ); + + $this->logInvalidation($result, $tags); + + if ($purgerError !== null) { + throw $purgerError; + } + + return $roOk && $etagOk; + } + + /** + * 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); } /** @@ -158,9 +214,10 @@ public function saveValue(ResourceObject $ro, int $ttl) $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)); - return $this->saver->__invoke($key, $value, $this->roPool, $tags, $ttl); + return $saved; } /** @@ -171,14 +228,15 @@ 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]); /** @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, $ttl)); - return $this->saver->__invoke($key, $value, $this->roPool, $tags, $ttl); + return $saved; } /** @@ -188,8 +246,8 @@ public function saveView(ResourceObject $ro, int $ttl) public function saveDonut(AbstractUri $uri, ResourceDonut $donut, int|null $sMaxAge, array $headerKeys): void { $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); + $this->logger->event(new SaveDonutContext((string) $uri, $sMaxAge)); assert($result, 'Donut save failed.'); } @@ -199,9 +257,10 @@ public function saveDonutView(ResourceObject $ro, int|null $ttl): bool $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)); - return $this->saver->__invoke($key, $resourceState, $this->roPool, $tags, $ttl); + return $saved; } /** @return list */ @@ -274,9 +333,9 @@ public function saveEtag(AbstractUri $uri, string $etag, string $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]); // Sanitize etag to remove reserved characters $this->saver->__invoke($etag, 'etag', $this->etagPool, $uniqueTags, $ttl); + $this->logger->event(new SaveEtagContext((string) $uri, $etag, $uniqueTags)); } 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..2b110753 100644 --- a/tests/CACHE_DEPENDENCY_TESTS.md +++ b/tests/CACHE_DEPENDENCY_TESTS.md @@ -79,7 +79,77 @@ 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`) | open | `CommandInterceptor`, `RefreshInterceptor` | A write whose `#[Refresh]`/`#[Purge]` annotations cause the nested purges | +| `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 | +| `invalidate` (`tags`/`roPool`/`etagPool`/`cdn`/`durationMs`) | event | `ResourceStorage::invalidateTags()` | Per-target outcome as status words: `roPool`/`etagPool` are `invalidated`\|`failed`, `cdn` is `purged`\|`failed` (best-effort; `failed` on outage without failing local invalidation) | +| `purge` | event | `QueryRepository::purge()` | An explicit purge request | +| `put_donut` / `refresh_donut` | event | `DonutRepository` | Donut store / rebuild | + +(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: + +```text +get uri=page://self/dep/level-one +├── depends_on parent=.../level-one child=.../level-two childTags=[_dep_level-two_, _dep_level-three_] [event] +├── save_value uri=.../level-one tags=[..., _dep_level-three_] ttl=31536000 [event] +├── get uri=page://self/dep/level-two +│ └── get uri=page://self/dep/level-three +│ └── (close) cache_miss layer=resource +└── (close) cache_miss layer=resource +``` + +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. + +## 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 | +| `testValidatorRejectsContextViolatingItsSchema` | A `cache_hit` without `layer` is rejected (proves drift is caught) | + +`ResourceStorageTest` pins the invalidation outcome and `GracefulLoggingTest` +pins resilience: + +| Test | Verifies | +|------|----------| +| `testInvalidateTagsRecordsSuccessfulOutcome` | `roPool`/`etagPool` are `invalidated`, `cdn` is `purged`, `durationMs` is recorded | +| `testInvalidateTagsTreatsPurgerFailureAsBestEffort` | A CDN purger outage does not fail local invalidation; recorded as `cdn=failed` | +| `GracefulLoggingTest::testCacheWorksWhenLoggerAlwaysThrows` | A logger that throws on every call never breaks cache reads/writes (SafeSemanticLogger) | ## ETag Invalidation Verification @@ -92,6 +162,27 @@ 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; under Swoole/RoadRunner a host should flush at the request + boundary. 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 can be **dropped** (empty flush) rather than merely interleaved. + 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; the default + PHP-FPM (one request per process) deployment is unaffected. +- **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 two are still distinguishable by the presence of a + `refresh_donut` event inside the scope; the close label is intentionally coarse. +- **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/`: diff --git a/tests/DonutCacheInterceptorTest.php b/tests/DonutCacheInterceptorTest.php index 36e53c01..3e68a3e5 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 @@ -58,21 +60,19 @@ public function testInitialRequest(): string /** @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); + $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..cb0cb356 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); } 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 79f659aa..38c710c0 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; @@ -16,9 +17,11 @@ class DonutQueryInterceptorPurgeTest extends TestCase { + use SemanticLogTreeTrait; + private ResourceInterface $resource; private QueryRepository $repository; - private RepositoryLoggerInterface $logger; + private SemanticLoggerInterface $logger; protected function setUp(): void { @@ -34,16 +37,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 16464983..83177f18 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; @@ -16,8 +17,10 @@ class DonutQueryInterceptorTest extends TestCase { + use SemanticLogTreeTrait; + private ResourceInterface $resource; - private RepositoryLoggerInterface $logger; + private SemanticLoggerInterface $logger; protected function setUp(): void { @@ -32,16 +35,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 @@ -69,22 +71,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/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); + + // A second access is served from cache: same stored ETag, and still no exception leaks out. + $cached = $resource->get('page://self/dep/level-one'); + $this->assertSame($ro->headers[Header::ETAG], $cached->headers[Header::ETAG]); + } +} diff --git a/tests/QueryRepositoryTest.php b/tests/QueryRepositoryTest.php index 3b13d7df..a209f8d7 100644 --- a/tests/QueryRepositoryTest.php +++ b/tests/QueryRepositoryTest.php @@ -14,6 +14,7 @@ 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 +36,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 +50,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 diff --git a/tests/RecordingSemanticLogger.php b/tests/RecordingSemanticLogger.php new file mode 100644 index 00000000..99ee2a5e --- /dev/null +++ b/tests/RecordingSemanticLogger.php @@ -0,0 +1,77 @@ + */ + 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); + } + + /** + * Types of every recorded entry (opens, events, closes) for sequence assertions + * + * @return list + */ + public function types(): array + { + $types = []; + foreach ([...$this->opens, ...$this->events, ...$this->closes] as $context) { + $type = $context::TYPE; + $types[] = is_string($type) ? $type : ''; + } + + return $types; + } +} 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 71854af0..d7dd7476 100644 --- a/tests/ResourceStorageTest.php +++ b/tests/ResourceStorageTest.php @@ -4,19 +4,25 @@ namespace BEAR\QueryRepository; +use BEAR\QueryRepository\Log\Context\InvalidateContext; +use BEAR\QueryRepository\Log\NullSemanticLogger; use BEAR\Resource\Uri; use FakeVendor\HelloWorld\Resource\Page\Index; +use Koriym\SemanticLogger\SemanticLoggerInterface; use PHPUnit\Framework\TestCase; use Ray\Di\ProviderInterface; +use RuntimeException; 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 +37,8 @@ public function get() }; return new ResourceStorage( - new RepositoryLogger(), - new NullPurger(), + $logger ?? new NullSemanticLogger(), + $purger ?? new NullPurger(), new UriTag(), new ResourceStorageSaver(), new GlobalServerContext(), @@ -56,4 +62,43 @@ public function testSaveGetStatic(): void $donut = $this->storage->getDonut($this->ro->uri); $this->assertInstanceOf(ResourceDonut::class, $donut); } + + public function testInvalidateTagsRecordsSuccessfulOutcome(): 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); + $this->assertTrue($context->cdnPurged); + $this->assertGreaterThanOrEqual(0, $context->durationMs); + $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->assertFalse($context->cdnPurged); + $this->assertSame('failed', $context->jsonSerialize()['cdn']); + } } diff --git a/tests/SafeSemanticLoggerTest.php b/tests/SafeSemanticLoggerTest.php new file mode 100644 index 00000000..b71c51a9 --- /dev/null +++ b/tests/SafeSemanticLoggerTest.php @@ -0,0 +1,133 @@ +open(new GetContext('page://self/x')); + $safe->close(new CacheMissContext('resource'), $id); + // The delegate throws on flush; the failure is swallowed and an empty log returned. + $this->assertSame([], $safe->flush()->toArray()['open']); + + // 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 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..709c94c3 --- /dev/null +++ b/tests/SemanticLogSchemaTest.php @@ -0,0 +1,138 @@ +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); + } + + 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 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', + 'context' => [], // missing "layer" + ], + ], + ], + ]; + $file = (string) tempnam(sys_get_temp_dir(), 'slog'); + file_put_contents($file, (string) json_encode($tree, JSON_UNESCAPED_SLASHES)); + + $this->expectException(RuntimeException::class); + ob_start(); + try { + (new SemanticLogValidator())->validate($file, dirname(__DIR__) . '/docs/schemas/context'); + } finally { + ob_get_clean(); + } + } +} diff --git a/tests/SemanticLogTreeTrait.php b/tests/SemanticLogTreeTrait.php new file mode 100644 index 00000000..53945ede --- /dev/null +++ b/tests/SemanticLogTreeTrait.php @@ -0,0 +1,188 @@ + 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); + } + + /** + * @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; + } +} 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 @@ +