From 4af5f43b2f1588307219f34037dc3bc098840c3a Mon Sep 17 00:00:00 2001 From: Jonathon Byrdziak Date: Sat, 4 Apr 2026 14:46:29 -0700 Subject: [PATCH] Fix lifecycle hooks ordering, add --force flags, pre-flight checks, and debug logging - Watcher now passes --force to stop/start so it never blocks on stale locks - ProtocolStop gets --force (-f) option matching ProtocolStart - post_start hooks now run after all other start steps complete and display - Container readiness check with Fibonacci backoff (up to 2min) before hooks - release:create aborts on dirty tree, unpulled remote changes, or push rejection - release:create rolls back local tag + VERSION commit if branch push fails - self:update --nightly fixed for detached HEAD (uses symbolic-ref) - Detailed logging throughout lifecycle hooks for debugging Co-Authored-By: Claude Opus 4.6 (1M context) --- src/Commands/ProtocolStart.php | 57 ++++++++++++++++- src/Commands/ProtocolStop.php | 11 +++- src/Commands/ProtocolUpdate.php | 13 +++- src/Commands/ReleaseCreate.php | 71 +++++++++++++++------ src/Helpers/Lifecycle.php | 107 +++++++++++++++++++++++++++++++- src/Helpers/ReleaseWatcher.php | 2 +- 6 files changed, 231 insertions(+), 30 deletions(-) diff --git a/src/Commands/ProtocolStart.php b/src/Commands/ProtocolStart.php index bba3456..d970f2d 100644 --- a/src/Commands/ProtocolStart.php +++ b/src/Commands/ProtocolStart.php @@ -234,7 +234,6 @@ private function startDirect(string $dir): int // duplicate stop+start cycle that kills what we just started. $this->provisionSlaveWatchers($dir, $ctx); $this->startDevServices($dir, $ctx); - $this->runPostStartHooks($dir, $ctx); $this->runSecurityAudit($dir, $ctx); $this->runSoc2Check($dir, $ctx); $this->verifyHealth($dir, $ctx); @@ -248,6 +247,12 @@ private function startDirect(string $dir): int $statusArgs = new ArrayInput(['--dir' => $dir]); $this->getApplication()->find('status')->run($statusArgs, $this->output); + // Wait for container readiness with Fibonacci backoff (up to 2 min) + // before running post_start hooks — all other steps must have + // completed and displayed their output first. + $this->waitForContainerReady($dir); + $this->runPostStartHooks($dir, $ctx); + return Command::SUCCESS; } @@ -680,13 +685,54 @@ private function startDevServices(string $dir, array $ctx): void } } + private function waitForContainerReady(string $dir): void + { + $runner = $this->runner; + $runner->run('Waiting for container readiness', function() use ($runner, $dir) { + $runner->log("dir={$dir}"); + + // Log what docker sees right now + $containerName = ContainerName::resolveFromDir($dir); + $runner->log("resolveFromDir container=" . ($containerName ?: '(none)')); + if (!$containerName) { + $names = Docker::getContainerNamesFromDockerComposeFile($dir); + $runner->log("compose containers=" . json_encode($names)); + } + + // List running docker containers for context + $ps = Shell::run("docker ps --format '{{.Names}} {{.Status}}' 2>&1"); + $runner->log("docker ps:\n" . ($ps ?: '(empty)')); + + $ready = Lifecycle::waitForContainer($dir, function($msg) use ($runner) { + $runner->log($msg); + }); + if (!$ready) { + throw new \RuntimeException('Container did not become ready within ' . Lifecycle::MAX_WAIT . ' seconds'); + } + }, 'READY'); + } + private function runPostStartHooks(string $dir, array $ctx): void { $runner = $this->runner; $runner->run('Post-start hooks', function() use ($runner, $dir, $ctx) { + $runner->log("dir={$dir} strategy={$ctx['strategy']}"); + + // Check protocol.json exists and is readable + $protocolJson = rtrim($dir, '/') . '/protocol.json'; + $runner->log("protocol.json exists=" . (is_file($protocolJson) ? 'yes' : 'no')); + if (is_file($protocolJson)) { + $raw = file_get_contents($protocolJson); + $decoded = json_decode($raw, true); + $runner->log("protocol.json lifecycle keys=" . json_encode( + array_keys($decoded['lifecycle'] ?? []) + )); + } + $hookKey = 'lifecycle.post_start'; if ($ctx['strategy'] === 'none') { $devHooks = Json::read('lifecycle.post_start_dev', null, $dir); + $runner->log("lifecycle.post_start_dev raw=" . json_encode($devHooks)); if (is_array($devHooks)) { $hookKey = 'lifecycle.post_start_dev'; $runner->log("strategy=none, using {$hookKey}"); @@ -694,8 +740,10 @@ private function runPostStartHooks(string $dir, array $ctx): void } $postStart = Json::read($hookKey, [], $dir); + $runner->log("{$hookKey} raw=" . json_encode($postStart)); + if (empty($postStart) || !is_array($postStart)) { - $runner->log("No {$hookKey} hooks configured"); + $runner->log("No {$hookKey} hooks configured — skipping"); return; } @@ -703,9 +751,12 @@ private function runPostStartHooks(string $dir, array $ctx): void $bgEnv = rtrim($dir, '/') . '/.env.deployment'; if (is_file($bgEnv)) { $envFile = $bgEnv; + $runner->log("envFile={$envFile}"); + } else { + $runner->log("no .env.deployment found"); } - $runner->log("Running " . count($postStart) . " {$hookKey} hook(s) in {$dir}"); + $runner->log("Dispatching " . count($postStart) . " {$hookKey} hook(s)"); Lifecycle::runPostStart($dir, function($msg) use ($runner) { $runner->log($msg); }, $envFile, $hookKey); diff --git a/src/Commands/ProtocolStop.php b/src/Commands/ProtocolStop.php index a0a9e58..8e61bb3 100644 --- a/src/Commands/ProtocolStop.php +++ b/src/Commands/ProtocolStop.php @@ -79,6 +79,7 @@ protected function configure(): void // configure an argument ->addArgument('project', InputArgument::OPTIONAL, 'Project name (for slave nodes, run from anywhere)') ->addOption('dir', 'd', InputOption::VALUE_OPTIONAL, 'Directory Path', null) + ->addOption('force', 'f', InputOption::VALUE_NONE, 'Force stop, ignoring any existing lock') // ... ; } @@ -96,8 +97,14 @@ protected function execute(InputInterface $input, OutputInterface $output): int $output->writeln(''); if (!$this->lock()) { - $output->writeln('The command is already running in another process.'); - return Command::SUCCESS; + if ($input->getOption('force')) { + $output->writeln('Forcing lock override...'); + $this->release(); + $this->lock(); + } else { + $output->writeln('The command is already running in another process. Use --force (-f) to override.'); + return Command::SUCCESS; + } } $dir = $this->resolveDirectory(); diff --git a/src/Commands/ProtocolUpdate.php b/src/Commands/ProtocolUpdate.php index e898fbf..a249ac4 100644 --- a/src/Commands/ProtocolUpdate.php +++ b/src/Commands/ProtocolUpdate.php @@ -82,10 +82,17 @@ protected function execute(InputInterface $input, OutputInterface $output): int Shell::passthru("git -C " . escapeshellarg($protocoldir) . " fetch --all --tags"); if ($input->getOption('nightly')) { - // Nightly: reset to branch tip - $branch = Git::branch($protocoldir) ?: 'main'; + // Nightly: checkout the branch and pull the tip. + // Git::branch() returns garbage in detached HEAD (e.g. from a + // previous tag checkout), so detect that and default to main. + $rawBranch = trim(Shell::run( + "git -C " . escapeshellarg($protocoldir) . " symbolic-ref --short HEAD 2>/dev/null" + )); + $branch = $rawBranch ?: 'main'; + $output->writeln("Updating to nightly ({$remote}/{$branch})"); - Shell::passthru("git -C " . escapeshellarg($protocoldir) . " reset --hard {$remote}/{$branch}"); + Shell::passthru("git -C " . escapeshellarg($protocoldir) . " checkout " . escapeshellarg($branch)); + Shell::passthru("git -C " . escapeshellarg($protocoldir) . " reset --hard " . escapeshellarg("{$remote}/{$branch}")); } else { // Release: find the latest semver tag $latestTag = trim(Shell::run( diff --git a/src/Commands/ReleaseCreate.php b/src/Commands/ReleaseCreate.php index 3ec690f..c0dbb31 100644 --- a/src/Commands/ReleaseCreate.php +++ b/src/Commands/ReleaseCreate.php @@ -122,22 +122,33 @@ protected function execute(InputInterface $input, OutputInterface $output): int // Check clean working tree $status = trim(Shell::run("git -C " . escapeshellarg($repo_dir) . " status --porcelain 2>/dev/null")); if ($status) { - $output->writeln('Warning: Working tree is not clean.'); + $output->writeln('Working tree is not clean. Commit your changes before creating a release.'); $output->writeln(''); $output->writeln($status); - $output->writeln(''); + return Command::FAILURE; + } - $helper = $this->getHelper('question'); - $question = new ConfirmationQuestion('Commit all changes before creating the release? [y/N] ', false); - if ($helper->ask($input, $output, $question)) { - Shell::run("git -C " . escapeshellarg($repo_dir) . " add -A"); - Shell::run("git -C " . escapeshellarg($repo_dir) . " commit -m " . escapeshellarg("Pre-release cleanup for {$version}")); - $output->writeln(' - Committed all changes'); - $output->writeln(''); - } else { - $output->writeln('Aborting. Commit or stash your changes first.'); - return Command::FAILURE; - } + // Fetch remote and check if local is behind + $remote = Git::remoteName($repo_dir) ?: 'origin'; + $branch = Git::branch($repo_dir); + Shell::run("git -C " . escapeshellarg($repo_dir) . " fetch " . escapeshellarg($remote) . " 2>&1"); + + $behind = (int) trim(Shell::run( + "git -C " . escapeshellarg($repo_dir) + . " rev-list --count HEAD.." . escapeshellarg("{$remote}/{$branch}") . " 2>/dev/null" + )); + if ($behind > 0) { + $output->writeln("Local branch '{$branch}' is {$behind} commit(s) behind {$remote}/{$branch}."); + $output->writeln('Pull the latest changes before creating a release.'); + return Command::FAILURE; + } + + $ahead = (int) trim(Shell::run( + "git -C " . escapeshellarg($repo_dir) + . " rev-list --count " . escapeshellarg("{$remote}/{$branch}") . "..HEAD 2>/dev/null" + )); + if ($ahead > 0) { + $output->writeln("Local branch is {$ahead} commit(s) ahead — these will be pushed with the release."); } // Check tag doesn't exist @@ -163,12 +174,34 @@ protected function execute(InputInterface $input, OutputInterface $output): int // Push if (!$input->getOption('no-push')) { - $remote = Git::remoteName($repo_dir) ?: 'origin'; - $branch = Git::branch($repo_dir); - - Shell::passthru("git -C " . escapeshellarg($repo_dir) . " push " . escapeshellarg($remote) . " " . escapeshellarg($branch)); - Shell::passthru("git -C " . escapeshellarg($repo_dir) . " push " . escapeshellarg($remote) . " " . escapeshellarg($version)); - $output->writeln(" - Pushed to {$remote}"); + // Push branch first — abort entirely if rejected + $branchPushResult = Shell::run( + "git -C " . escapeshellarg($repo_dir) . " push " . escapeshellarg($remote) . " " . escapeshellarg($branch) . " 2>&1", + $branchPushExit + ); + if ($branchPushExit !== 0) { + $output->writeln('Branch push rejected. Removing local tag and undoing VERSION commit.'); + $output->writeln($branchPushResult); + // Rollback: delete local tag and undo the VERSION commit + Shell::run("git -C " . escapeshellarg($repo_dir) . " tag -d " . escapeshellarg($version) . " 2>/dev/null"); + Shell::run("git -C " . escapeshellarg($repo_dir) . " reset --soft HEAD~1 2>/dev/null"); + Shell::run("git -C " . escapeshellarg($repo_dir) . " checkout -- VERSION 2>/dev/null"); + $output->writeln('Rolled back local tag and VERSION commit. Pull the latest changes and try again.'); + return Command::FAILURE; + } + $output->writeln(" - Pushed branch to {$remote}"); + + // Push tag + $tagPushResult = Shell::run( + "git -C " . escapeshellarg($repo_dir) . " push " . escapeshellarg($remote) . " " . escapeshellarg($version) . " 2>&1", + $tagPushExit + ); + if ($tagPushExit !== 0) { + $output->writeln('Tag push failed.'); + $output->writeln($tagPushResult); + return Command::FAILURE; + } + $output->writeln(" - Pushed tag {$version} to {$remote}"); // Create GitHub Release $draft = $input->getOption('draft'); diff --git a/src/Helpers/Lifecycle.php b/src/Helpers/Lifecycle.php index dc67ce7..432a67a 100644 --- a/src/Helpers/Lifecycle.php +++ b/src/Helpers/Lifecycle.php @@ -2,9 +2,73 @@ namespace Gitcd\Helpers; use Gitcd\Utils\Json; +use Gitcd\Helpers\Docker; +use Gitcd\Helpers\ContainerName; class Lifecycle { + /** Maximum total wait time for container readiness (seconds). */ + public const MAX_WAIT = 120; + + /** + * Wait for the container to be running using Fibonacci backoff. + * + * Sequence: 1, 1, 2, 3, 5, 8, 13, 21, 34, 55 … + * Gives up after MAX_WAIT seconds total elapsed. + * + * @return bool true if container became ready, false on timeout + */ + public static function waitForContainer(string $repoDir, ?callable $logger = null): bool + { + $containerName = ContainerName::resolveFromDir($repoDir); + if (!$containerName) { + // Fallback: grab names from compose file + $names = Docker::getContainerNamesFromDockerComposeFile($repoDir); + $containerName = $names[0] ?? null; + } + + if (!$containerName) { + if ($logger) $logger("No container name resolved — skipping readiness wait"); + return true; + } + + if ($logger) $logger("Waiting for container '{$containerName}' to be ready (max " . self::MAX_WAIT . "s)…"); + + $elapsed = 0; + $a = 1; + $b = 1; + + while ($elapsed < self::MAX_WAIT) { + if (Docker::isDockerContainerRunning($containerName)) { + if ($logger) $logger("Container '{$containerName}' is running after {$elapsed}s"); + return true; + } + + $delay = min($a, self::MAX_WAIT - $elapsed); + if ($delay <= 0) { + break; + } + + if ($logger) $logger("Container not ready, retrying in {$delay}s (elapsed {$elapsed}s)…"); + sleep($delay); + $elapsed += $delay; + + // Fibonacci step + $next = $a + $b; + $a = $b; + $b = $next; + } + + // Final check after the last sleep + if (Docker::isDockerContainerRunning($containerName)) { + if ($logger) $logger("Container '{$containerName}' is running after {$elapsed}s"); + return true; + } + + if ($logger) $logger("Container '{$containerName}' not ready after {$elapsed}s — giving up"); + return false; + } + /** * Run post_start lifecycle hooks from protocol.json. * @@ -23,13 +87,33 @@ class Lifecycle public static function runPostStart(string $repoDir, ?callable $logger = null, ?string $envFile = null, string $hookKey = 'lifecycle.post_start'): void { $hooks = Json::read($hookKey, [], $repoDir); + + if ($logger) { + $logger("hookKey={$hookKey} repoDir={$repoDir}"); + $logger("raw hooks value: " . json_encode($hooks)); + } + if (!is_array($hooks) || empty($hooks)) { + if ($logger) $logger("No hooks to run (empty or not an array)"); return; } + // Log container resolution so we can see what exec will target + $containerName = ContainerName::resolveActive($repoDir); + if ($logger) { + $logger("resolveActive container=" . ($containerName ?: '(none)')); + if (!$containerName) { + $fallbackNames = Docker::getContainerNamesFromDockerComposeFile($repoDir); + $logger("fallback compose containers=" . json_encode($fallbackNames)); + } + $isRunning = $containerName ? Docker::isDockerContainerRunning($containerName) : false; + $logger("container running=" . ($isRunning ? 'yes' : 'no')); + } + foreach ($hooks as $i => $hook) { $hook = trim($hook); if ($hook === '') { + if ($logger) $logger("[hook {$i}] skipped (empty string)"); continue; } @@ -37,8 +121,27 @@ public static function runPostStart(string $repoDir, ?callable $logger = null, ? $cmd = "protocol exec -T -d " . escapeshellarg(rtrim($repoDir, '/')) . " " . escapeshellarg($hook) . " 2>&1"; - if ($logger) $logger("[hook {$i}] exec: {$hook}"); - Shell::run($cmd); + if ($logger) $logger("[hook {$i}] cmd: {$cmd}"); + + $output = Shell::run($cmd, $exitCode); + + if ($logger) { + $logger("[hook {$i}] exit_code={$exitCode}"); + if ($output !== null && trim($output) !== '') { + // Log output line by line to keep log readable + foreach (explode("\n", trim($output)) as $line) { + $logger("[hook {$i}] output: {$line}"); + } + } else { + $logger("[hook {$i}] output: (empty)"); + } + } + + if ($exitCode !== 0 && $logger) { + $logger("[hook {$i}] WARNING: hook exited with non-zero code {$exitCode}"); + } } + + if ($logger) $logger("All {$hookKey} hooks complete"); } } diff --git a/src/Helpers/ReleaseWatcher.php b/src/Helpers/ReleaseWatcher.php index aa5c62f..8e780dd 100644 --- a/src/Helpers/ReleaseWatcher.php +++ b/src/Helpers/ReleaseWatcher.php @@ -464,7 +464,7 @@ private function protocolStopStart(string $stopDir, string $startDir): void $stopArg = escapeshellarg($stopDir); $startArg = escapeshellarg($startDir); - $cmd = "nohup sh -c 'php {$phpBin} stop --dir={$stopArg} && php {$phpBin} start --dir={$startArg}'" + $cmd = "nohup sh -c 'php {$phpBin} stop --force --dir={$stopArg} && php {$phpBin} start --force --dir={$startArg}'" . " >> " . escapeshellarg($logFile) . " 2>&1