Rebuild cache observability on Koriym.SemanticLogger

CHANGELOG.md

@@ -5,6 +5,41 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
+## [Unreleased]
+
+### Added
+- Cache observability is now built on [Koriym.SemanticLogger](https://github.com/koriym/Koriym.SemanticLogger): an open/event/close tree whose nesting **is** the embed/dependency structure (a parent's embedded children nest under it). Typed `AbstractContext` subclasses live in `src/Log/Context/` with per-context JSON Schemas in `docs/schemas/context/`.
+- `SafeSemanticLogger` (best-effort decorator) guarantees logging never breaks cache reads/writes. The DI default bound via `SafeSemanticLoggerProvider` in `DonutCacheModule` is `SafeSemanticLogger(new SemanticLogger())`; `NullSemanticLogger` is the constructor-parameter fallback when no logger is injected.
+- `invalidate` context records per-target outcomes as self-describing status words: `roPool`/`etagPool` (`invalidated`|`failed`), `cdn` (`purged`|`failed`), plus `durationMs`. A CDN purge failure is fail-closed: the local pools are invalidated first and the outcome is logged as `cdn: failed`, then the purge exception propagates so a write does not silently leave stale CDN content.
+- Logs validate against their schemas in tests via `SemanticLogValidator` (`SemanticLogTreeTrait`), and `vendor/bin/stree` renders the cache log as a readable tree (`demo/run-dependency.php`, `demo/run-donut.php`).
+- Direct (non-AOP) top-level `put()`, `purge()` and `invalidateTags()` calls are rooted in `manual_store` / `manual_purge` / `manual_invalidate` scopes so their save/purge/invalidate events stay visible; an event with no enclosing scope would otherwise be dropped at flush.
+- `cache_error` context: emitted when the cache layer itself throws (e.g. cache server down) in the read/write interceptors, so a cache outage is distinguishable from a genuine cold-cache miss in the log.
+- `saved` outcome field on the save contexts (`save_value` / `save_view` / `save_donut` / `save_donut_view` / `save_etag`): the cache pool's accept/reject result, so a silently failed store no longer looks like a successful save.
+- `tags` (invalidation tags) on all five save contexts, so a save can be correlated with the `invalidate` events that later bust it.
+- `put_skipped` context: emitted when a miss is not followed by a put, so a miss without save events reads as a recorded skip, not a lost write. `reason` is `etag-present`, `error-code` (with the actual response `code`, also emitted by `CacheInterceptor` on a non-200 GET), or `not-cacheable` (a donut page re-rendered from its template is never stored as a rendered page).
+- `source` field on the `command` context naming the producing interceptor (`CommandInterceptor` / `DonutCommandInterceptor` / `RefreshInterceptor`).
+- `operation` field on `cache_error` (`read` / `write`), so the failing side of a degraded cache layer is recorded.
+- `cdn` on `invalidate` is now tri-state: `purged` (a configured purger ran), `failed` (it threw), `skipped` (the bound purger is `NullPurger`, i.e. no CDN configured) — previously a no-op NullPurger was indistinguishable from a real purge (`purged`).
+- `ttl` field on `save_etag`, completing the save contexts; all `ttl` descriptions state the convention that 31536000 is the `never` expiry placeholder and event-driven invalidation is the intended eviction path.
+- `log_session_broken` sentinel: when `SafeSemanticLogger` must discard a broken logging session (e.g. a LIFO violation), the recovery flush returns this scope carrying the cause instead of a silent empty log — "no records" is never misread as "no cache activity".
+- Negative TTL clamping: a past `expiryAt` or a negative `expirySecond`/ttl argument is clamped to 0 at the `QueryRepository`/`ResourceStorage` boundary, matching the `"minimum": 0` the schemas declare.
+- The demos verify themselves: all three scripts print the semantic log (tree + pretty JSON) and validate the flushed session offline against `docs/schemas/context`, printing a one-line verdict and exiting non-zero on any violation. `demo/run-dependency.php` scenario 3 is now command-driven — a PUT on `LevelThree` (whose new `onPut` carries `#[Purge]`) opens a `command` scope whose purge cascades to level-two/level-one — alongside the manual `manual_purge` entry kind in scenario 6. `demo/run.php` binds real in-memory pools so its log shows genuine cache hits (the `QueryRepositoryModule` default `NullAdapter` made every GET miss).
+
+### Deprecated
+- `RepositoryLogger`, `RepositoryLoggerInterface`, `StructuredRepositoryLoggerInterface` and `NullRepositoryLogger`. Internal cache code now logs through `Koriym\SemanticLogger\SemanticLoggerInterface`; the legacy flat interface remains bound for BC but receives no internal events.
+
+### Removed
+- `docs/schemas/repository-log.json` (the flat op-string log format it described is gone; per-context schemas in `docs/schemas/context/` replace it).
+
+### Changed
+- Cache logging call sites (`QueryRepository`, `ResourceStorage`, `DonutRepository`, `CacheInterceptor`, `AbstractDonutCacheInterceptor`, `CommandInterceptor`, `RefreshInterceptor`) now emit typed contexts through `SemanticLoggerInterface` instead of `RepositoryLoggerInterface::log()`.
+- `SaveDonutContext`/`SaveDonutViewContext`: the misleading `sMaxAge` field is renamed to `ttl` — the value is the cache entry TTL, never a CDN s-maxage.
+- `SaveEtagContext`/`SaveDonutViewContext`: `surrogateKeys` renamed to `tags`; all save contexts now consistently report invalidation tags under `tags`.
+- Command scopes are opened even for failed writes: a 4xx response closes with `command_result` (code 4xx) and no invalidation events, recording that the purge/refresh was correctly skipped instead of vanishing from the log.
+- Removed the post-save `assert()` in `ResourceStorage::saveDonut()`: with assertions enabled it threw AFTER the `saved: false` event was logged, contradicting quiet-failure recording.
+- The pre-write-cleanup rule for `invalidate` events is redefined as a machine-applicable predicate: an invalidate is pre-write cleanup when, within the SAME scope's event stream, a later `save_*` event's tags include the invalidate's tags — regardless of the enclosing scope type (a `#[Refresh]` command's second put runs inside the command scope, and `depends_on` events may sit between the cleanup invalidate and the saves). In donut scopes match against `save_etag`/`save_donut_view` (`save_donut`'s tags may exclude the URI tag). This supersedes the earlier scope-type/"immediately followed" formulation in the schemas and guides.
+- Added runtime dependency `koriym/semantic-logger`.
+
 ## [1.16.2] - 2026-06-29
 
 ### Fixed

CLAUDE.md

@@ -207,4 +207,4 @@ Follows PSR-12 coding standards with PHP_CodeSniffer.
 - BEAR.Sunday LLM docs: https://bearsunday.github.io/llms-full.txt
 - This package LLM docs: https://bearsunday.github.io/BEAR.QueryRepository/llms-full.txt
 - Cache manual: https://bearsunday.github.io/manuals/1.0/en/cache.html
-- Log schema: https://bearsunday.github.io/BEAR.QueryRepository/schemas/repository-log.json
+- Log schemas: https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/ (one JSON Schema per log context, e.g. https://bearsunday.github.io/BEAR.QueryRepository/schemas/context/save_value.json)

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",

demo/AppModule.php

@@ -5,9 +5,13 @@
 namespace FakeVendor\DemoApp;
 
 use BEAR\QueryRepository\QueryRepositoryModule;
+use BEAR\RepositoryModule\Annotation\EtagPool;
+use BEAR\RepositoryModule\Annotation\ResourceObjectPool;
 use BEAR\Resource\Module\ResourceModule;
 use Ray\Di\AbstractModule;
 use Ray\Di\Scope;
+use Symfony\Component\Cache\Adapter\AdapterInterface;
+use Symfony\Component\Cache\Adapter\ArrayAdapter;
 
 class AppModule extends AbstractModule
 {
@@ -19,5 +23,9 @@ protected function configure()
         $this->bind()->annotatedWith('storage_dir')->toInstance(__DIR__ . '/tmp')->in(Scope::SINGLETON);
         $this->install(new ResourceModule(__NAMESPACE__));
         $this->install(new QueryRepositoryModule);
+        // Real in-memory pools: QueryRepositoryModule's default is a NullAdapter,
+        // under which every demo GET would miss and the log could never show a hit.
+        $this->bind(AdapterInterface::class)->annotatedWith(ResourceObjectPool::class)->to(ArrayAdapter::class);
+        $this->bind(AdapterInterface::class)->annotatedWith(EtagPool::class)->to(ArrayAdapter::class);
     }
 }

demo/run-dependency.php

@@ -8,7 +8,9 @@
  * This script demonstrates cache dependency logging to help understand:
  * - Cache hit/miss operations
  * - Dependency registration (depends-on)
+ * - Command-driven invalidation (a #[Purge] write opens a command scope)
  * - Cascade invalidation (invalidate-etag)
+ * - Manual purge (a direct purge() call roots a manual_purge scope)
  *
  * Resources used (from tests/Fake/fake-app):
  * - LevelOne -> LevelTwo -> LevelThree (3-level dependency chain)
@@ -18,12 +20,15 @@
 use BEAR\QueryRepository\FakeEtagPoolModule;
 use BEAR\QueryRepository\ModuleFactory;
 use BEAR\QueryRepository\QueryRepositoryInterface;
-use BEAR\QueryRepository\RepositoryLoggerInterface;
 use BEAR\Resource\ResourceInterface;
 use BEAR\Resource\Uri;
+use Koriym\SemanticLogger\SemanticLoggerInterface;
+use Koriym\SemanticLogger\Stree\RenderConfig;
+use Koriym\SemanticLogger\Stree\TreeRenderer;
 use Ray\Di\Injector;
 
 require dirname(__DIR__) . '/vendor/autoload.php';
+require __DIR__ . '/validate.php';
 
 // Scenario descriptions (for humans)
 echo <<<'SCENARIOS'
@@ -38,17 +43,22 @@
 2. Re-access level-one
    - Should be cache-hit
 
-3. Purge level-three (grandchild)
-   - Should cascade invalidate level-two and level-one
+3. Write to level-three (PUT)
+   - #[Purge] on LevelThree::onPut invalidates level-three's cache
+   - The surrogate-key cascade busts level-two and level-one
+   - The log shows a command scope (method/annotations/source)
+     driving the purge — cause and effect in one subtree
 
-4. Re-access level-one after purge
+4. Re-access level-one after the write
    - All three should be cache-miss (regenerated)
 
 5. Access ParentA and ParentB
    - Both embed ChildC (shared dependency)
 
-6. Purge child-c
+6. Purge child-c (manual repository purge)
    - Should invalidate both ParentA and ParentB
+   - A direct purge() roots a top-level manual_purge scope —
+     a different entry kind than the command scope in 3
 
 7. Re-access both parents after purge
    - Both should be cache-miss (regenerated)
@@ -65,36 +75,31 @@
 
 $resource = $injector->getInstance(ResourceInterface::class);
 $repository = $injector->getInstance(QueryRepositoryInterface::class);
-$logger = $injector->getInstance(RepositoryLoggerInterface::class);
-
-// Execute scenarios silently
-$logger->log('request-start', ['uri' => 'page://self/dep/level-one']);
-$resource->get('page://self/dep/level-one');                    // 1. Initial access
-
-$logger->log('request-start', ['uri' => 'page://self/dep/level-one']);
-$resource->get('page://self/dep/level-one');                    // 2. Re-access (cache-hit)
-
-$logger->log('request-start', ['uri' => 'page://self/dep/level-three', 'method' => 'purge']);
-$repository->purge(new Uri('page://self/dep/level-three'));     // 3. Purge grandchild
-
-$logger->log('request-start', ['uri' => 'page://self/dep/level-one']);
-$resource->get('page://self/dep/level-one');                    // 4. Re-access after purge
-
-$logger->log('request-start', ['uri' => 'page://self/dep/parent-a']);
-$resource->get('page://self/dep/parent-a');                     // 5a. Access ParentA
-
-$logger->log('request-start', ['uri' => 'page://self/dep/parent-b']);
-$resource->get('page://self/dep/parent-b');                     // 5b. Access ParentB
-
-$logger->log('request-start', ['uri' => 'page://self/dep/child-c', 'method' => 'purge']);
-$repository->purge(new Uri('page://self/dep/child-c'));         // 6. Purge shared child
-
-$logger->log('request-start', ['uri' => 'page://self/dep/parent-a']);
-$resource->get('page://self/dep/parent-a');                     // 7a. Re-access ParentA
-
-$logger->log('request-start', ['uri' => 'page://self/dep/parent-b']);
-$resource->get('page://self/dep/parent-b');                     // 7b. Re-access ParentB
-
-// Output logs only
-echo "=== Cache Log ===" . PHP_EOL;
-echo $logger . PHP_EOL;
+$logger = $injector->getInstance(SemanticLoggerInterface::class);
+
+// Execute scenarios. Embedded child GETs nest under their parent GET, so the
+// log's open/close tree IS the embed/dependency tree (no reconstruction).
+$resource->get('page://self/dep/level-one');                // 1. Initial access (cache-miss chain)
+$resource->get('page://self/dep/level-one');                // 2. Re-access (cache-hit)
+$resource->put('page://self/dep/level-three');              // 3. Write: #[Purge] command (cascade)
+$resource->get('page://self/dep/level-one');                // 4. Re-access after the write (rebuilt)
+$resource->get('page://self/dep/parent-a');                 // 5a. Access ParentA
+$resource->get('page://self/dep/parent-b');                 // 5b. Access ParentB
+$repository->purge(new Uri('page://self/dep/child-c'));     // 6. Manual purge (manual_purge scope)
+$resource->get('page://self/dep/parent-a');                 // 7a. Re-access ParentA
+$resource->get('page://self/dep/parent-b');                 // 7b. Re-access ParentB
+
+$log = $logger->flush();
+
+// Human/AI-readable tree (open = embed scope, close = hit/miss, events = saves/invalidations)
+echo "=== Cache Log Tree ===" . PHP_EOL;
+echo (new TreeRenderer())->render($log->toArray(), new RenderConfig(true, 0.0, 1000, true)) . PHP_EOL;
+
+// Machine-readable JSON conforming to the published schemas (validated below
+// against the local schema files; also: `vendor/bin/stree <file>`)
+echo PHP_EOL . "=== Cache Log JSON ===" . PHP_EOL;
+echo json_encode($log, JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES) . PHP_EOL;
+
+// The demo verifies itself: the flushed log must validate offline against
+// docs/schemas/context (exits non-zero on any violation)
+validateLog($log);

demo/run-donut.php

@@ -18,15 +18,18 @@
 use BEAR\QueryRepository\FakeEtagPoolModule;
 use BEAR\QueryRepository\ModuleFactory;
 use BEAR\QueryRepository\QueryRepositoryInterface;
-use BEAR\QueryRepository\RepositoryLoggerInterface;
 use BEAR\QueryRepository\ResourceStorageInterface;
 use BEAR\QueryRepository\UriTag;
 use BEAR\Resource\ResourceInterface;
 use BEAR\Resource\Uri;
+use Koriym\SemanticLogger\SemanticLoggerInterface;
+use Koriym\SemanticLogger\Stree\RenderConfig;
+use Koriym\SemanticLogger\Stree\TreeRenderer;
 use Madapaja\TwigModule\TwigModule;
 use Ray\Di\Injector;
 
 require dirname(__DIR__) . '/vendor/autoload.php';
+require __DIR__ . '/validate.php';
 
 // Scenario descriptions (for humans)
 echo <<<'SCENARIOS'
@@ -62,21 +65,25 @@
 $resource = $injector->getInstance(ResourceInterface::class);
 $repository = $injector->getInstance(QueryRepositoryInterface::class);
 $storage = $injector->getInstance(ResourceStorageInterface::class);
-$logger = $injector->getInstance(RepositoryLoggerInterface::class);
+$logger = $injector->getInstance(SemanticLoggerInterface::class);
 
-// Execute scenarios silently
-$logger->log('request-start', ['uri' => 'page://self/html/blog-posting']);
-$resource->get('page://self/html/blog-posting');                           // 1. Initial access
+// Execute scenarios. The donut GET scope wraps the embedded comment fetch.
+$resource->get('page://self/html/blog-posting');     // 1. Initial access
+$resource->get('page://self/html/blog-posting');     // 2. Re-access (cache-hit)
+$repository->purge(new Uri('page://self/html/comment')); // 3. Manual purge of comment (top-level)
+$resource->get('page://self/html/blog-posting');     // 4. Access after invalidation
 
-$logger->log('request-start', ['uri' => 'page://self/html/blog-posting']);
-$resource->get('page://self/html/blog-posting');                           // 2. Re-access (cache-hit)
+$log = $logger->flush();
 
-$logger->log('request-start', ['uri' => 'page://self/html/comment', 'method' => 'invalidate']);
-$storage->invalidateTags([(new UriTag())(new Uri('page://self/html/comment'))]);  // 3. Invalidate comment
+// Human/AI-readable tree (open = embed scope, close = hit/miss, events = saves/invalidations)
+echo "=== Cache Log Tree ===" . PHP_EOL;
+echo (new TreeRenderer())->render($log->toArray(), new RenderConfig(true, 0.0, 1000, true)) . PHP_EOL;
 
-$logger->log('request-start', ['uri' => 'page://self/html/blog-posting']);
-$resource->get('page://self/html/blog-posting');                           // 4. Access after invalidation
+// Machine-readable JSON conforming to the published schemas (validated below
+// against the local schema files; also: `vendor/bin/stree <file>`)
+echo PHP_EOL . "=== Cache Log JSON ===" . PHP_EOL;
+echo json_encode($log, JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES) . PHP_EOL;
 
-// Output logs only
-echo "=== Cache Log ===" . PHP_EOL;
-echo $logger . PHP_EOL;
+// The demo verifies itself: the flushed log must validate offline against
+// docs/schemas/context (exits non-zero on any violation)
+validateLog($log);

demo/run.php

@@ -4,6 +4,9 @@
 
 use BEAR\Resource\ResourceInterface;
 use FakeVendor\DemoApp\AppModule;
+use Koriym\SemanticLogger\SemanticLoggerInterface;
+use Koriym\SemanticLogger\Stree\RenderConfig;
+use Koriym\SemanticLogger\Stree\TreeRenderer;
 use Ray\Di\Injector;
 
 function echoRo(BEAR\Resource\ResourceObject $ro)
@@ -19,9 +22,11 @@ function echoRo(BEAR\Resource\ResourceObject $ro)
 /* @var $loader \Composer\Autoload\ClassLoader */
 $loader = require \dirname(__DIR__) . '/vendor/autoload.php';
 $loader->addPsr4('FakeVendor\DemoApp\\', __DIR__);
+require __DIR__ . '/validate.php';
 
+$injector = new Injector(new AppModule, __DIR__ . '/tmp');
 /* @var $resource ResourceInterface */
-$resource = (new Injector(new AppModule, __DIR__ . '/tmp'))->getInstance(ResourceInterface::class);
+$resource = $injector->getInstance(ResourceInterface::class);
 
 echoRo($resource->uri('app://self/user')(['id' => 1])); // create cache
 
@@ -32,3 +37,17 @@ function echoRo(BEAR\Resource\ResourceObject $ro)
 echoRo($resource->uri('app://self/user')(['id' => 1])); // return cache
 
 echoRo($resource->uri('app://self/user')(['id' => 1])); // return cache
+
+// The semantic cache log of the session above: an open/event/close tree
+// (GET scopes, the onPatch command scope, saves and hits) plus the
+// schema-conforming JSON. This is the machine-verifiable view of the
+// TTL-less, event-driven cache the HTTP output only hints at via Age.
+$log = $injector->getInstance(SemanticLoggerInterface::class)->flush();
+
+echo PHP_EOL . "=== Cache Log Tree ===" . PHP_EOL;
+echo (new TreeRenderer())->render($log->toArray(), new RenderConfig(true, 0.0, 1000, true)) . PHP_EOL;
+
+echo PHP_EOL . "=== Cache Log JSON ===" . PHP_EOL;
+echo json_encode($log, JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES) . PHP_EOL;
+
+validateLog($log);