observe: keep body generations aligned with retained logs (#134)

.claude/skills/bear-observe/SKILL.md

@@ -242,7 +242,7 @@ $log = $logger->flush();                    // その場で受け取る(以降
 | 依存の伝播 | `save_*` の `tags` ↔ `invalidate` の `tags` の突き合わせ。`depends_on` を出すのは `#[Cacheable]` の親だけで、donut の親は出さない(§4) |
 | 何回リソースが走ったか | `resource_request` の数。N+1 は同じ URI の兄弟が並ぶ形で出る |
 | どこで時間を使ったか | `durationMs`。親から子を引いた残りがその層の自前のコスト |
-| 何を返したか | `body_ref` のファイル(`var/log/<context>/es-bodies/`) |
+| 何を返したか | `body_ref` のファイル(`var/log/<context>/es-bodies/<generation>/`。generation はリクエストごとのディレクトリで、ログと同じ本数だけ残る) |
 
 読み間違えやすい 4 点(いずれも実測):
 

.claude/skills/bear-observe/templates/DevModule.php

@@ -8,19 +8,38 @@
 use BEAR\EventSourcing\Module\EventSourcingModule;
 use BEAR\EventSourcing\Recorded;
 use BEAR\EventSourcing\RecordedMethods;
+use BEAR\EventSourcing\Resource\BodyStoreException;
 use BEAR\EventSourcing\Resource\BodyStoreInterface;
 use BEAR\EventSourcing\Resource\FileBodyStore;
 use BEAR\EventSourcing\Resource\SemanticLogInvoker;
 use BEAR\Package\AbstractAppModule;
 use BEAR\QueryRepository\DevQueryRepositoryLogModule;
 use BEAR\RepositoryModule\Annotation\EtagPool;
 use BEAR\RepositoryModule\Annotation\ResourceObjectPool;
+use BEAR\Resource\AbstractRequest;
 use BEAR\Resource\InvokerInterface;
+use BEAR\Resource\ResourceObject;
 use Koriym\SemanticLogger\SemanticLoggerInterface;
 use Override;
 use Ray\Di\Scope;
 use Symfony\Component\Cache\Adapter\AdapterInterface;
 
+use function array_slice;
+use function bin2hex;
+use function count;
+use function glob;
+use function gmdate;
+use function is_dir;
+use function is_file;
+use function max;
+use function microtime;
+use function random_bytes;
+use function rmdir;
+use function sort;
+use function sprintf;
+
+use const GLOB_ONLYDIR;
+
 /**
  * Observation context: `dev-` prefix on the app context (`dev-hal-app`, `cli-dev-hal-app`).
  *
@@ -33,11 +52,31 @@ final class DevModule extends AbstractAppModule
 {
     private const ORIGINAL_INVOKER = 'original_invoker';
 
+    /**
+     * Body generations retained alongside log sessions (same count passed to
+     * DevQueryRepositoryLogModule below): a log's body_ref keeps resolving for as long as the
+     * log itself survives, and neither is pruned without the other (issue #134).
+     *
+     * Matches DevQueryRepositoryLogModule's own default so aligning the two lifetimes does not
+     * shorten the log history the bear-observe skill tells people to read back through.
+     */
+    private const int KEEP_GENERATIONS = 100;
+    /**
+     * Ownership marker FileBodyStore writes into each directory it manages; its own copy of this
+     * name is private, so pruning re-states it rather than miscounting a directory it does not own.
+     */
+    private const string BODY_STORE_MARKER = '.bear-es-bodies';
+
     #[Override]
     protected function configure(): void
     {
-        $bodyDir = $this->appMeta->logDir . '/es-bodies';
-        FileBodyStore::clearDirectory($bodyDir);
+        $bodiesRoot = $this->appMeta->logDir . '/es-bodies';
+        self::pruneStaleGenerations($bodiesRoot, self::KEEP_GENERATIONS);
+        // One subdirectory per stored body set: FileBodyStore's sequence restarts at 1 on every
+        // injector build, so a directory shared across sessions would let two sessions overwrite
+        // each other's numbered files. The key sorts chronologically, matching the shape of
+        // DevQueryRepositoryLogModule's own session filenames.
+        $bodyDir = $bodiesRoot . '/' . self::generationKey();
 
         $this->rename(InvokerInterface::class, self::ORIGINAL_INVOKER);
         $this->bind(InvokerInterface::class)
@@ -53,12 +92,34 @@ protected function configure(): void
         // reads visible in the tree.
         $this->bind(RecordedMethods::class)->annotatedWith(Recorded::class)
             ->toInstance(new RecordedMethods(RecordedMethods::WITH_READS));
-        $this->bind(BodyStoreInterface::class)->toInstance(new FileBodyStore($bodyDir));
+        // Deferred, not `new FileBodyStore($bodyDir)`: that constructor creates its directory
+        // eagerly, and configure() runs before routing knows the request method. A request that
+        // records nothing (an OPTIONS preflight never reaches the recorded methods, and
+        // LogFileWriter::write() returns early when nothing was opened) would then add a
+        // generation without adding a log, letting the body window advance past the log window
+        // until a retained log's body_ref points at a pruned generation. Creating the directory
+        // only when a body is stored makes generations strictly rarer than log sessions.
+        $this->bind(BodyStoreInterface::class)->toInstance(
+            new class ($bodyDir) implements BodyStoreInterface {
+                private FileBodyStore|null $store = null;
+
+                public function __construct(private readonly string $dir)
+                {
+                }
+
+                public function __invoke(AbstractRequest $request, ResourceObject $ro): string|null
+                {
+                    $this->store ??= new FileBodyStore($this->dir);
+
+                    return ($this->store)($request, $ro);
+                }
+            },
+        );
         $this->install(new EventSourcingModule());
 
         // The cache log module owns the writer and the shutdown flush, so the application
         // writes no flush of its own.
-        $this->install(new DevQueryRepositoryLogModule($this->appMeta->logDir . '/observe'));
+        $this->install(new DevQueryRepositoryLogModule($this->appMeta->logDir . '/observe', self::KEEP_GENERATIONS));
         // One request, one tree: the resource invoker records into the logger the sink flushes.
         $this->bind(SemanticLoggerInterface::class)
             ->toProvider(ObserveLoggerProvider::class)->in(Scope::SINGLETON);
@@ -69,4 +130,65 @@ protected function configure(): void
         $this->bind(AdapterInterface::class)->annotatedWith(EtagPool::class)
             ->toProvider(DevPoolProvider::class)->in(Scope::SINGLETON);
     }
+
+    /** Sortable per-request key: zero-padded so lexical order is chronological order. */
+    private static function generationKey(): string
+    {
+        $now = microtime(true);
+        $seconds = (int) $now;
+        $micro = (int) (($now - (float) $seconds) * 1_000_000.0);
+
+        return gmdate('Ymd-His', $seconds) . '-' . sprintf('%06d', $micro) . '-' . bin2hex(random_bytes(4));
+    }
+
+    /**
+     * Deletes body generations beyond $keep, oldest first.
+     *
+     * Shares its retention count with LogFileWriter::prune(). A generation is only created when a
+     * body is actually stored, which requires a recorded request, which writes a log session — so
+     * generations are always rarer than logs and the body window spans at least as far back as the
+     * log window. A retained log's `body_ref` therefore still resolves. The converse does not hold
+     * and is not claimed: a crashed process can leave a generation whose log was never written,
+     * and that generation is pruned on count alone.
+     */
+    private static function pruneStaleGenerations(string $bodiesRoot, int $keep): void
+    {
+        // Only directories carrying FileBodyStore's ownership marker. Counting anything else
+        // toward the cap over-prunes: a foreign directory that sorts newer than the generations
+        // (any lowercase name does — ASCII puts letters after digits) inflates the overflow while
+        // the oldest-first slice stays entirely ours, so one stray `es-bodies/tmp` permanently
+        // costs one real generation and shrinks the body window below the log window.
+        $generations = [];
+        foreach (glob($bodiesRoot . '/*', GLOB_ONLYDIR) ?: [] as $candidate) {
+            if (! is_file($candidate . '/' . self::BODY_STORE_MARKER)) {
+                continue;
+            }
+
+            $generations[] = $candidate;
+        }
+
+        sort($generations);
+        $overflow = max(0, count($generations) - $keep);
+        foreach (array_slice($generations, 0, $overflow) as $stale) {
+            try {
+                FileBodyStore::clearDirectory($stale);
+            } catch (BodyStoreException) {
+                // Skipped, not reported: a sibling process pruning the same generation wins the
+                // race, and a directory without FileBodyStore's ownership marker is refused on
+                // purpose. Neither is this module's to fix, and an unowned directory is left
+                // where it is rather than deleted.
+                continue;
+            }
+
+            // The directory is empty by now, so removing it is cosmetic: leaving one behind
+            // orphans nothing, because the log that referenced its bodies is pruned too. A
+            // concurrent prune can win the race between these two calls, so an unchecked
+            // rmdir() would emit a warning for a state that is already the desired one.
+            if (! is_dir($stale)) {
+                continue;
+            }
+
+            @rmdir($stale);
+        }
+    }
 }

src/Module/DeferredFileBodyStore.php

@@ -0,0 +1,43 @@
+<?php
+
+declare(strict_types=1);
+
+namespace MyVendor\BeMart\Module;
+
+use BEAR\EventSourcing\Resource\BodyStoreInterface;
+use BEAR\EventSourcing\Resource\FileBodyStore;
+use BEAR\Resource\AbstractRequest;
+use BEAR\Resource\ResourceObject;
+use Override;
+
+/**
+ * Creates the generation directory only once a body is actually stored.
+ *
+ * `FileBodyStore::__construct()` creates its directory eagerly, and `ObserveModule::configure()`
+ * runs on every injector build — before routing decides the request method. A request that records
+ * nothing (an `OPTIONS` preflight never reaches `SemanticLogInvoker`'s recorded methods, and
+ * `LogFileWriter::write()` returns early when nothing was opened) would therefore add a generation
+ * directory while adding no log session. Retention counts the two separately, so the body window
+ * would advance ahead of the log window and eventually prune a generation a still-retained log's
+ * `body_ref` points at — the failure {@see \MyVendor\BeMart\Module\ObserveModule} exists to prevent.
+ *
+ * Deferring construction makes a generation strictly imply a stored body, and a stored body implies
+ * a recorded request, so generations can only ever be rarer than log sessions. Bodies then outlive
+ * the logs referencing them for any retention count the two share.
+ */
+final class DeferredFileBodyStore implements BodyStoreInterface
+{
+    private FileBodyStore|null $store = null;
+
+    public function __construct(private readonly string $dir)
+    {
+    }
+
+    #[Override]
+    public function __invoke(AbstractRequest $request, ResourceObject $ro): string|null
+    {
+        $this->store ??= new FileBodyStore($this->dir);
+
+        return ($this->store)($request, $ro);
+    }
+}

src/Module/ObserveModule.php

@@ -8,6 +8,7 @@
 use BEAR\EventSourcing\Module\EventSourcingModule;
 use BEAR\EventSourcing\Recorded;
 use BEAR\EventSourcing\RecordedMethods;
+use BEAR\EventSourcing\Resource\BodyStoreException;
 use BEAR\EventSourcing\Resource\BodyStoreInterface;
 use BEAR\EventSourcing\Resource\FileBodyStore;
 use BEAR\EventSourcing\Resource\ParamsFilterInterface;
@@ -23,6 +24,22 @@
 use Ray\Di\Scope;
 use Symfony\Component\Cache\Adapter\AdapterInterface;
 
+use function array_slice;
+use function bin2hex;
+use function count;
+use function glob;
+use function gmdate;
+use function is_dir;
+use function is_file;
+use function max;
+use function microtime;
+use function random_bytes;
+use function rmdir;
+use function sort;
+use function sprintf;
+
+use const GLOB_ONLYDIR;
+
 /**
  * Observation context: `observe-` prefix on the app context (`cli-observe-fake-hal-app`).
  *
@@ -57,13 +74,34 @@ final class ObserveModule extends AbstractAppModule
      */
     public const array EXTRA_CREDENTIALS = ['resetKey', 'authKey'];
 
+    /**
+     * Body generations retained alongside log sessions (same count passed to
+     * DevQueryRepositoryLogModule below): a log's body_ref keeps resolving for as long as the
+     * log itself survives, and neither is pruned without the other (issue #134).
+     *
+     * Matches DevQueryRepositoryLogModule's own default so aligning the two lifetimes does not
+     * shorten the log history the bear-observe skill tells people to read back through.
+     */
+    public const int KEEP_GENERATIONS = 100;
+    /**
+     * Ownership marker FileBodyStore writes into each directory it manages; its own copy of this
+     * name is private, so pruning re-states it rather than miscounting a directory it does not own.
+     */
+    private const string BODY_STORE_MARKER = '.bear-es-bodies';
+
     private const ORIGINAL_INVOKER = 'original_invoker';
 
     #[Override]
     protected function configure(): void
     {
-        $bodyDir = $this->appMeta->logDir . '/es-bodies';
-        FileBodyStore::clearDirectory($bodyDir);
+        $bodiesRoot = $this->appMeta->logDir . '/es-bodies';
+        self::pruneStaleGenerations($bodiesRoot, self::KEEP_GENERATIONS);
+        // One subdirectory per stored body set: FileBodyStore's sequence restarts at 1 on every
+        // injector build, so a directory shared across sessions would let two sessions overwrite
+        // each other's numbered files. The key sorts chronologically, matching the shape of
+        // DevQueryRepositoryLogModule's own session filenames. DeferredFileBodyStore creates it
+        // only if a body is actually stored, which is what keeps generations rarer than logs.
+        $bodyDir = $bodiesRoot . '/' . self::generationKey();
 
         $this->bind(ParamsFilterInterface::class)->annotatedWith(Filtered::class)
             ->toInstance(new SensitiveParamsFilter(self::EXTRA_CREDENTIALS));
@@ -80,12 +118,12 @@ protected function configure(): void
         $this->bind(RecordedMethods::class)->annotatedWith(Recorded::class)
             ->toInstance(new RecordedMethods(RecordedMethods::WITH_READS));
         $this->bind(BodyStoreInterface::class)
-            ->toInstance(new ExcludedResponseBodyStore(new FileBodyStore($bodyDir)));
+            ->toInstance(new ExcludedResponseBodyStore(new DeferredFileBodyStore($bodyDir)));
         $this->install(new EventSourcingModule());
 
         // The cache log module owns the writer and the shutdown flush, so the application
         // writes no flush of its own.
-        $this->install(new DevQueryRepositoryLogModule($this->appMeta->logDir . '/observe'));
+        $this->install(new DevQueryRepositoryLogModule($this->appMeta->logDir . '/observe', self::KEEP_GENERATIONS));
         // One request, one tree: the resource invoker records into the logger the sink flushes.
         $this->bind(SemanticLoggerInterface::class)
             ->toProvider(ObserveLoggerProvider::class)->in(Scope::SINGLETON);
@@ -96,4 +134,65 @@ protected function configure(): void
         $this->bind(AdapterInterface::class)->annotatedWith(EtagPool::class)
             ->toProvider(DevPoolProvider::class)->in(Scope::SINGLETON);
     }
+
+    /** Sortable per-request key: zero-padded so lexical order is chronological order. */
+    private static function generationKey(): string
+    {
+        $now = microtime(true);
+        $seconds = (int) $now;
+        $micro = (int) (($now - (float) $seconds) * 1_000_000.0);
+
+        return gmdate('Ymd-His', $seconds) . '-' . sprintf('%06d', $micro) . '-' . bin2hex(random_bytes(4));
+    }
+
+    /**
+     * Deletes body generations beyond $keep, oldest first.
+     *
+     * Shares its retention count with LogFileWriter::prune(). A generation is only created when a
+     * body is actually stored ({@see DeferredFileBodyStore}), which requires a recorded request,
+     * which writes a log session — so generations are always rarer than logs and the body window
+     * spans at least as far back as the log window. A retained log's `body_ref` therefore still
+     * resolves. The converse does not hold and is not claimed: a crashed process can leave a
+     * generation whose log was never written, and that generation is pruned on count alone.
+     */
+    private static function pruneStaleGenerations(string $bodiesRoot, int $keep): void
+    {
+        // Only directories carrying FileBodyStore's ownership marker. Counting anything else
+        // toward the cap over-prunes: a foreign directory that sorts newer than the generations
+        // (any lowercase name does — ASCII puts letters after digits) inflates the overflow while
+        // the oldest-first slice stays entirely ours, so one stray `es-bodies/tmp` permanently
+        // costs one real generation and shrinks the body window below the log window.
+        $generations = [];
+        foreach (glob($bodiesRoot . '/*', GLOB_ONLYDIR) ?: [] as $candidate) {
+            if (! is_file($candidate . '/' . self::BODY_STORE_MARKER)) {
+                continue;
+            }
+
+            $generations[] = $candidate;
+        }
+
+        sort($generations);
+        $overflow = max(0, count($generations) - $keep);
+        foreach (array_slice($generations, 0, $overflow) as $stale) {
+            try {
+                FileBodyStore::clearDirectory($stale);
+            } catch (BodyStoreException) {
+                // Skipped, not reported: a sibling process pruning the same generation wins the
+                // race, and a directory without FileBodyStore's ownership marker is refused on
+                // purpose. Neither is this module's to fix, and an unowned directory is left
+                // where it is rather than deleted.
+                continue;
+            }
+
+            // The directory is empty by now, so removing it is cosmetic: leaving one behind
+            // orphans nothing, because the log that referenced its bodies is pruned too. A
+            // concurrent prune can win the race between these two calls, so an unchecked
+            // rmdir() would emit a warning for a state that is already the desired one.
+            if (! is_dir($stale)) {
+                continue;
+            }
+
+            @rmdir($stale);
+        }
+    }
 }