diff --git a/.claude/skills/bear-observe/SKILL.md b/.claude/skills/bear-observe/SKILL.md index 70d71d64..b425e64c 100644 --- a/.claude/skills/bear-observe/SKILL.md +++ b/.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//es-bodies/`) | +| 何を返したか | `body_ref` のファイル(`var/log//es-bodies//`。generation はリクエストごとのディレクトリで、ログと同じ本数だけ残る) | 読み間違えやすい 4 点(いずれも実測): diff --git a/.claude/skills/bear-observe/templates/DevModule.php b/.claude/skills/bear-observe/templates/DevModule.php index f01d4829..edc80320 100644 --- a/.claude/skills/bear-observe/templates/DevModule.php +++ b/.claude/skills/bear-observe/templates/DevModule.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\SemanticLogInvoker; @@ -15,12 +16,30 @@ 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); + } + } } diff --git a/src/Module/DeferredFileBodyStore.php b/src/Module/DeferredFileBodyStore.php new file mode 100644 index 00000000..f26f7a39 --- /dev/null +++ b/src/Module/DeferredFileBodyStore.php @@ -0,0 +1,43 @@ +store ??= new FileBodyStore($this->dir); + + return ($this->store)($request, $ro); + } +} diff --git a/src/Module/ObserveModule.php b/src/Module/ObserveModule.php index 33167f7a..76e0b0c9 100644 --- a/src/Module/ObserveModule.php +++ b/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); + } + } } diff --git a/tests/Module/ObserveModuleBodyRetentionTest.php b/tests/Module/ObserveModuleBodyRetentionTest.php new file mode 100644 index 00000000..c930f24e --- /dev/null +++ b/tests/Module/ObserveModuleBodyRetentionTest.php @@ -0,0 +1,289 @@ +bind(SemanticLoggerInterface::class)->toInstance($this->logger); + // TestModule's DevModule chain wraps BecomingInterface in DevBecoming, which + // flushes the semantic logger after every becoming — the same conflict + // ObserveModule's own docblock keeps it out of `dev` for. Undo it here so a + // resource that runs a Be transition (e.g. page://self/product) still closes + // its resource_request scope instead of finding it already flushed out from + // under it. + $this->bind(BecomingInterface::class)->to(Becoming::class); + // Fresh, process-local pools per session: DevPoolProvider's on-disk + // FilesystemAdapter is what makes a real CLI run's second request a hit — + // exactly what an isolated test must not depend on, or leave behind. + $this->bind(AdapterInterface::class)->annotatedWith(ResourceObjectPool::class) + ->toInstance(new ArrayAdapter()); + $this->bind(AdapterInterface::class)->annotatedWith(EtagPool::class) + ->toInstance(new ArrayAdapter()); + } + }; + + $injector = new Injector($wrapper, dirname(__DIR__, 2) . '/var/tmp/test'); + + return $injector->getInstance(ResourceInterface::class); + } + + /** @return array */ + private static function flushToTree(SemanticLoggerInterface $logger): array + { + /** @var array */ + return json_decode(json_encode($logger->flush(), JSON_THROW_ON_ERROR), true, 512, JSON_THROW_ON_ERROR); + } + + private static function bodyPath(string $bodyRef): string + { + return str_starts_with($bodyRef, 'file://') ? substr($bodyRef, 7) : $bodyRef; + } + + private static function removeTree(string $dir): void + { + if (! is_dir($dir)) { + return; + } + + $iterator = new RecursiveIteratorIterator( + new RecursiveDirectoryIterator($dir, FilesystemIterator::SKIP_DOTS), + RecursiveIteratorIterator::CHILD_FIRST, + ); + foreach ($iterator as $file) { + /** @var FilesystemIterator $file phpcs and psalm both accept the SPL leaf type here */ + $file->isDir() ? rmdir($file->getPathname()) : unlink($file->getPathname()); + } + + rmdir($dir); + } + + public function testBodyWrittenInOneInjectorGenerationSurvivesALaterInjectorCreation(): void + { + $logger1 = new SemanticLogger(); + $resource1 = $this->buildSession($logger1); + + $ro1 = $resource1->get('page://self/products'); + $this->assertSame(200, $ro1->code, 'fixture must actually reach the products page'); + + $tree1 = self::flushToTree($logger1); + $bodyRef1 = $tree1['open'][0]['open'][0]['close']['context']['body_ref'] ?? null; + $this->assertIsString($bodyRef1, 'the nested app:// call must record a body_ref'); + $bodyPath1 = self::bodyPath($bodyRef1); + $this->assertFileExists($bodyPath1, 'the body this session just wrote must exist right after writing it'); + $bytesBefore = (string) file_get_contents($bodyPath1); + + // A later injector creation: a brand new ObserveModule::configure() run, the same shape + // as a second `php bin/observe.php` process starting. Same context, so the same + // logDir/es-bodies root — the exact scenario issue #134 broke: FileBodyStore's + // clearDirectory() wiped every earlier session's bodies out from under this second run. + // + // This session's own request records no body at all (page://self/product resolves its + // data through a direct MediaQuery, no nested app:// call — see + // ExcludedResponseBodyStore's own contract for why the outer page:// response itself + // never gets a body_ref), so nothing in this session can recreate session 1's file by + // coincidence: if it is gone after this session, this session's own clearing broke it. + $logger2 = new SemanticLogger(); + $resource2 = $this->buildSession($logger2); + + $ro2 = $resource2->get('page://self/product', ['productCode' => 'sample-001']); + $this->assertSame(200, $ro2->code, 'second session fixture must actually reach the product page'); + $tree2 = self::flushToTree($logger2); + $this->assertArrayNotHasKey( + 'body_ref', + $tree2['open'][0]['close']['context'], + 'fixture precondition: this session must itself write zero bodies, so a survival check ' + . 'right after it cannot pass by the second session coincidentally recreating the same file', + ); + + $this->assertFileExists( + $bodyPath1, + "the first session's body_ref must still resolve after a later injector creation that wrote no " + . 'bodies of its own (issue #134)', + ); + $this->assertSame( + $bytesBefore, + (string) file_get_contents($bodyPath1), + "the first session's body content must be unchanged", + ); + + // A third session that does write a body must land in its own generation, never reusing + // (and so overwriting) the first session's numbered file. + $logger3 = new SemanticLogger(); + $resource3 = $this->buildSession($logger3); + + $ro3 = $resource3->get('page://self/products'); + $this->assertSame(200, $ro3->code, 'third session fixture must also reach the products page'); + $tree3 = self::flushToTree($logger3); + $bodyRef3 = $tree3['open'][0]['open'][0]['close']['context']['body_ref'] ?? null; + $this->assertIsString($bodyRef3, 'the third session must also record its own body_ref'); + $bodyPath3 = self::bodyPath($bodyRef3); + $this->assertNotSame($bodyPath1, $bodyPath3, 'each body-writing session must use its own generation'); + + $this->assertFileExists($bodyPath1, "the first session's body_ref must still resolve after a third session"); + $this->assertSame( + $bytesBefore, + (string) file_get_contents($bodyPath1), + "the first session's body content must remain unchanged after a third session", + ); + } + + public function testAnInjectorThatRecordsNothingAddsNoGeneration(): void + { + // configure() runs before routing knows the request method, so a build that goes on to + // record nothing (an OPTIONS preflight, a process that never dispatches) must not consume + // a generation. If it did, the body window would advance without the log window and + // retention would eventually prune a generation a retained log still points at. + $this->buildSession(new SemanticLogger()); + $this->buildSession(new SemanticLogger()); + $this->buildSession(new SemanticLogger()); + + $this->assertSame( + [], + self::generations(), + 'building an injector without storing a body must not create a generation directory', + ); + } + + public function testGenerationsBeyondTheRetentionCountArePrunedOldestFirst(): void + { + $root = dirname(__DIR__, 2) . '/var/log/' . self::CONTEXT . '/es-bodies'; + mkdir($root, 0775, true); + // One more than the module keeps, so the deletion branch has to run. The `.bear-es-bodies` + // marker is what FileBodyStore::clearDirectory() checks before deleting anything, so a + // generation without it is refused — planting it is what makes these fixtures real. + $planted = []; + for ($i = 0; $i <= ObserveModule::KEEP_GENERATIONS; $i++) { + $dir = $root . '/' . sprintf('20200101-000000-%06d-0000000%d', $i, $i % 10); + mkdir($dir, 0775, true); + file_put_contents($dir . '/.bear-es-bodies', ''); + file_put_contents($dir . '/000001.json', '{}'); + $planted[] = $dir; + } + + $this->buildSession(new SemanticLogger()); + + $survivors = self::generations(); + $this->assertCount( + ObserveModule::KEEP_GENERATIONS, + $survivors, + 'the retention count is the ceiling, and the deletion branch must enforce it', + ); + $this->assertNotContains($planted[0], $survivors, 'the oldest generation must be the one pruned'); + $this->assertContains( + $planted[ObserveModule::KEEP_GENERATIONS], + $survivors, + 'the newest generation must survive', + ); + } + + public function testAForeignDirectoryDoesNotCostARealGeneration(): void + { + $root = dirname(__DIR__, 2) . '/var/log/' . self::CONTEXT . '/es-bodies'; + mkdir($root, 0775, true); + // `tmp` sorts AFTER the timestamped names (ASCII puts letters after digits), so counting it + // inflates the overflow while the oldest-first slice stays entirely ours — the shape that + // silently costs one real generation per stray directory. + $foreign = $root . '/tmp'; + mkdir($foreign, 0775, true); + + $owned = []; + for ($i = 0; $i < ObserveModule::KEEP_GENERATIONS; $i++) { + $dir = $root . '/' . sprintf('20200101-000000-%06d-0000000%d', $i, $i % 10); + mkdir($dir, 0775, true); + file_put_contents($dir . '/.bear-es-bodies', ''); + $owned[] = $dir; + } + + $this->buildSession(new SemanticLogger()); + + $survivors = self::generations(); + $this->assertContains($owned[0], $survivors, 'exactly the retention count is owned, so none may be pruned'); + $this->assertContains($foreign, $survivors, 'a directory the body store does not own must be left alone'); + } + + /** @return list */ + private static function generations(): array + { + $found = glob(dirname(__DIR__, 2) . '/var/log/' . self::CONTEXT . '/es-bodies/*', GLOB_ONLYDIR); + + return $found === false ? [] : $found; + } +}