ECC/tests/hooks/observe-nosurvive-warning.test.js

/**
 * Regression tests for silent observer non-survival in observe.sh (#2489)
 *
 * On native Windows (Git Bash / MSYS2) the lazy-started observer is reaped when
 * the hook process exits and its Job Object closes. start-observer.sh's own
 * liveness check runs inside that still-living process tree, so it always sees a
 * healthy observer and prints "Observer started (PID: N)". The next hook
 * invocation then found the dead PID, deleted the PID file via
 * _CHECK_OBSERVER_RUNNING, and restarted -- silently, once per tool call,
 * forever. Users were left with an observer-start.log full of success lines and
 * an observer that never completed a cycle.
 *
 * The fix records the "well-formed PID that is no longer alive" case, counts
 * consecutive non-survivals in ${PROJECT_DIR}/.observer-nosurvive-count, and
 * logs one explanatory warning when the streak reaches
 * ECC_OBSERVER_NOSURVIVE_WARN_AFTER (default 3). Finding the observer alive
 * resets the streak.
 *
 * These tests drive the real observe.sh through the sandbox harness established
 * by observe-signal-counter-race.test.js.
 *
 * Run with: node tests/hooks/observe-nosurvive-warning.test.js
 */

const assert = require('assert');
const path = require('path');
const fs = require('fs');
const os = require('os');
const { spawn, spawnSync } = require('child_process');

let passed = 0;
let failed = 0;

function test(name, fn) {
  try {
    fn();
    console.log(`  ✓ ${name}`);
    passed++;
  } catch (err) {
    console.log(`  ✗ ${name}`);
    console.log(`    Error: ${err.message}`);
    failed++;
  }
}

async function asyncTest(name, fn) {
  try {
    await fn();
    console.log(`  ✓ ${name}`);
    passed++;
  } catch (err) {
    console.log(`  ✗ ${name}`);
    console.log(`    Error: ${err.message}`);
    failed++;
  }
}

function createTempDir() {
  return fs.mkdtempSync(path.join(os.tmpdir(), 'ecc-nosurvive-'));
}

function cleanupDir(dir) {
  try {
    fs.rmSync(dir, { recursive: true, force: true });
  } catch {
    // ignore cleanup errors
  }
}

const repoRoot = path.resolve(__dirname, '..', '..');
const observeShPath = path.join(repoRoot, 'skills', 'continuous-learning-v2', 'hooks', 'observe.sh');

const isWindows = process.platform === 'win32';
const hasPython = !isWindows && spawnSync('python3', ['--version']).status === 0;

const STREAK_FILE = '.observer-nosurvive-count';
const WARN_MARKER = 'did not survive to the next hook invocation';

// Build a self-contained observe.sh sandbox (stub detect-project.sh +
// homunculus-dir.sh, SKILL_ROOT patched to the sandbox) with the observer
// enabled, so the lazy-start branch under test is reached.
function buildSandbox() {
  const testDir = createTempDir();
  const projectDir = path.join(testDir, 'project');
  fs.mkdirSync(projectDir, { recursive: true });

  const skillRoot = path.join(testDir, 'skill');
  const scriptsDir = path.join(skillRoot, 'scripts');
  const scriptsLibDir = path.join(scriptsDir, 'lib');
  const hooksDir = path.join(skillRoot, 'hooks');
  fs.mkdirSync(scriptsLibDir, { recursive: true });
  fs.mkdirSync(hooksDir, { recursive: true });

  fs.writeFileSync(
    path.join(scriptsDir, 'detect-project.sh'),
    [
      '#!/bin/bash',
      'PROJECT_ID="test-project"',
      'PROJECT_NAME="test-project"',
      `PROJECT_ROOT="${projectDir}"`,
      `PROJECT_DIR="${projectDir}"`,
      'CLV2_PYTHON_CMD="python3"',
      ''
    ].join('\n')
  );

  // HOME is set to projectDir when observe.sh runs, so CONFIG_DIR resolves
  // under it. The observer must read as enabled for the lazy-start block to run.
  const configDir = path.join(projectDir, '.local', 'share', 'ecc-homunculus');
  fs.mkdirSync(configDir, { recursive: true });
  fs.writeFileSync(
    path.join(configDir, 'config.json'),
    JSON.stringify({ observer: { enabled: true } })
  );
  fs.writeFileSync(
    path.join(scriptsLibDir, 'homunculus-dir.sh'),
    [
      '#!/bin/bash',
      '_clv2_resolve_homunculus_dir() { printf "%s\\n" "$HOME/.local/share/ecc-homunculus"; }',
      ''
    ].join('\n')
  );

  let observeContent = fs.readFileSync(observeShPath, 'utf8');
  const skillRootMarker = 'SKILL_ROOT="$(cd "$SCRIPT_DIR/.." && pwd)"';
  // Fail fast if observe.sh's SKILL_ROOT definition drifts; otherwise the
  // no-op replace would leave the sandbox pointing at the real skill tree.
  assert.ok(
    observeContent.includes(skillRootMarker),
    'observe.sh SKILL_ROOT definition changed; update the sandbox rewrite'
  );
  observeContent = observeContent.replace(skillRootMarker, `SKILL_ROOT="${skillRoot}"`);
  const testObserve = path.join(hooksDir, 'observe.sh');
  fs.writeFileSync(testObserve, observeContent, { mode: 0o755 });

  return { testDir, projectDir, testObserve };
}

// Run observe.sh once against the sandbox. Resolves when the process exits.
function runObserve(testObserve, projectDir, extraEnv) {
  const input = JSON.stringify({
    tool_name: 'Read',
    tool_input: { file_path: '/tmp/test.txt' },
    session_id: 'test-session',
    cwd: projectDir
  });
  return new Promise((resolve, reject) => {
    const child = spawn('bash', [testObserve, 'post'], {
      env: {
        ...process.env,
        HOME: projectDir,
        CLAUDE_CODE_ENTRYPOINT: 'cli',
        ECC_HOOK_PROFILE: 'standard',
        ECC_SKIP_OBSERVE: '0',
        CLAUDE_PROJECT_DIR: projectDir,
        ...extraEnv
      },
      stdio: ['pipe', 'ignore', 'pipe']
    });
    let stderr = '';
    // Fail the test on a hung hook rather than waiting forever.
    const timer = setTimeout(() => {
      child.kill('SIGKILL');
      reject(new Error('observe.sh timed out'));
    }, 20000);
    child.stderr.on('data', (chunk) => { stderr += chunk; });
    // A broken observe.sh must fail the test, not be silently swallowed.
    child.on('close', (code, signal) => {
      clearTimeout(timer);
      if (code === 0 && signal === null) {
        resolve();
      } else {
        reject(new Error(`observe.sh failed code=${code} signal=${signal}: ${stderr.trim()}`));
      }
    });
    child.on('error', (err) => {
      clearTimeout(timer);
      reject(err);
    });
    child.stdin.end(input);
  });
}

// A well-formed PID that is guaranteed not to be alive: spawn a trivial command
// and reuse its PID after it has exited. Matches the shape observe.sh validates
// (positive integer > 1), unlike a hardcoded sentinel.
function deadPid() {
  const result = spawnSync('true');
  assert.ok(result.pid > 1, 'expected a usable PID from the probe process');
  return result.pid;
}

function readStreak(projectDir) {
  const streakFile = path.join(projectDir, STREAK_FILE);
  if (!fs.existsSync(streakFile)) {
    return null;
  }
  return parseInt(fs.readFileSync(streakFile, 'utf8').trim(), 10);
}

function readStartLog(projectDir) {
  const logFile = path.join(projectDir, 'observer-start.log');
  return fs.existsSync(logFile) ? fs.readFileSync(logFile, 'utf8') : '';
}

console.log('\n=== observe.sh observer non-survival warning (#2489) ===\n');

test('observe.sh records non-survival when clearing a live-looking stale PID', () => {
  const content = fs.readFileSync(observeShPath, 'utf8');
  assert.ok(
    /OBSERVER_DIED=true/.test(content),
    'the stale-PID branch of _CHECK_OBSERVER_RUNNING should record the death'
  );
  assert.ok(
    content.includes('_NOTE_OBSERVER_NOSURVIVE') && content.includes('_RESET_OBSERVER_NOSURVIVE_STREAK'),
    'observe.sh should define both the streak counter and its reset'
  );
});

test('the streak increment runs under the lazy-start lock, never unlocked', () => {
  const content = fs.readFileSync(observeShPath, 'utf8');
  // observe.sh fires on every tool call, so an unlocked read-modify-write on
  // the streak file would lose increments or double-log the warning -- the same
  // race the signal counter hit in #2296. The increment must therefore live in
  // _START_OBSERVER_LOGGED, which every call site invokes inside the
  // flock/lockfile/mkdir lazy-start lock.
  const starter = content.match(/_START_OBSERVER_LOGGED\(\)\s*\{[\s\S]*?\n\}/);
  assert.ok(starter, 'observe.sh should still define _START_OBSERVER_LOGGED');
  assert.ok(
    starter[0].includes('_NOTE_OBSERVER_NOSURVIVE'),
    'the streak increment should run inside _START_OBSERVER_LOGGED, under the lazy-start lock'
  );
  // Every _START_OBSERVER_LOGGED call site must be inside a lock branch.
  const callSites = content.split('\n').filter((line) => /^\s+_START_OBSERVER_LOGGED\s*$/.test(line));
  assert.strictEqual(callSites.length, 3, 'expected the three locked lazy-start call sites');
});

test('the non-survival warning is threshold-gated, not logged every call', () => {
  const content = fs.readFileSync(observeShPath, 'utf8');
  assert.ok(
    /ECC_OBSERVER_NOSURVIVE_WARN_AFTER/.test(content),
    'the threshold should be overridable via ECC_OBSERVER_NOSURVIVE_WARN_AFTER'
  );
  assert.ok(
    /\[ "\$streak" -eq "\$warn_after" \]/.test(content),
    'warning should fire on equality so it logs once per streak, not once per tool call'
  );
});

// A dead PID left behind by a reaped observer must produce an explanatory
// warning once the streak reaches the threshold.
async function runWarnsAtThreshold() {
  const { testDir, projectDir, testObserve } = buildSandbox();
  try {
    fs.writeFileSync(path.join(projectDir, '.observer.pid'), `${deadPid()}\n`);
    await runObserve(testObserve, projectDir, { ECC_OBSERVER_NOSURVIVE_WARN_AFTER: '1' });

    assert.strictEqual(readStreak(projectDir), 1, 'first non-survival should record a streak of 1');
    const log = readStartLog(projectDir);
    assert.ok(
      log.includes(WARN_MARKER),
      `observer-start.log should explain the non-survival, got: ${log.trim() || '(empty)'}`
    );
    assert.ok(
      log.includes('ECC_OBSERVER_NOSURVIVE_WARN_AFTER'),
      'the warning should name the threshold knob'
    );
  } finally {
    cleanupDir(testDir);
  }
}

// Below the threshold the streak advances but stays quiet -- this is what keeps
// the warning signal rather than one line per tool call.
async function runSilentBelowThreshold() {
  const { testDir, projectDir, testObserve } = buildSandbox();
  try {
    fs.writeFileSync(path.join(projectDir, '.observer.pid'), `${deadPid()}\n`);
    await runObserve(testObserve, projectDir, { ECC_OBSERVER_NOSURVIVE_WARN_AFTER: '3' });

    assert.strictEqual(readStreak(projectDir), 1, 'streak should advance to 1');
    assert.ok(
      !readStartLog(projectDir).includes(WARN_MARKER),
      'no warning should be logged before the streak reaches the threshold'
    );

    // Second non-survival: still below a threshold of 3.
    fs.writeFileSync(path.join(projectDir, '.observer.pid'), `${deadPid()}\n`);
    await runObserve(testObserve, projectDir, { ECC_OBSERVER_NOSURVIVE_WARN_AFTER: '3' });

    assert.strictEqual(readStreak(projectDir), 2, 'streak should advance to 2');
    assert.ok(
      !readStartLog(projectDir).includes(WARN_MARKER),
      'still no warning at streak 2 with a threshold of 3'
    );
  } finally {
    cleanupDir(testDir);
  }
}

// An all-zero threshold ("00" passes a digits-only check but compares as zero)
// must fall back to the default. Otherwise the streak, which only grows, could
// never equal it and the diagnostic would be silently disabled.
async function runRejectsZeroThreshold() {
  const { testDir, projectDir, testObserve } = buildSandbox();
  try {
    for (let i = 0; i < 3; i++) {
      fs.writeFileSync(path.join(projectDir, '.observer.pid'), `${deadPid()}\n`);
      await runObserve(testObserve, projectDir, { ECC_OBSERVER_NOSURVIVE_WARN_AFTER: '00' });
    }
    assert.strictEqual(readStreak(projectDir), 3, 'streak should still advance with a bogus threshold');
    const log = readStartLog(projectDir);
    assert.ok(
      log.includes(WARN_MARKER),
      '"00" should fall back to the default threshold of 3 and warn, not disable the diagnostic'
    );
    assert.ok(
      log.includes('(currently 3)'),
      'the warning should report the normalized threshold, not the raw "00"'
    );
  } finally {
    cleanupDir(testDir);
  }
}

// "00" is zero with or without the base-10 conversion, so it does not exercise
// it. "08" does: without `10#` bash reads it as octal, and an invalid octal
// digit is an arithmetic error that aborts the whole hook under `set -e`.
async function runLeadingZeroThreshold() {
  const { testDir, projectDir, testObserve } = buildSandbox();
  try {
    fs.writeFileSync(path.join(projectDir, '.observer.pid'), `${deadPid()}\n`);
    // runObserve rejects on a non-zero exit, so an octal abort fails here.
    await runObserve(testObserve, projectDir, { ECC_OBSERVER_NOSURVIVE_WARN_AFTER: '08' });

    assert.strictEqual(readStreak(projectDir), 1, 'streak should advance under an "08" threshold');
    assert.ok(
      !readStartLog(projectDir).includes(WARN_MARKER),
      '"08" should be read as decimal 8, so a streak of 1 must not warn yet'
    );
  } finally {
    cleanupDir(testDir);
  }
}

// If the counter cannot be persisted, the file stays below the threshold and
// every later invocation would re-increment in memory and warn again -- turning
// the once-per-streak diagnostic into once-per-tool-call spam. An unpersisted
// increment must therefore stay silent, while the hook still exits 0.
async function runSilentWhenCounterUnwritable() {
  const { testDir, projectDir, testObserve } = buildSandbox();
  try {
    // A directory where the counter file goes makes the `>` redirection fail.
    fs.mkdirSync(path.join(projectDir, STREAK_FILE), { recursive: true });

    for (let i = 0; i < 2; i++) {
      fs.writeFileSync(path.join(projectDir, '.observer.pid'), `${deadPid()}\n`);
      // runObserve rejects on a non-zero exit, so this also asserts the hook
      // never fails the tool call just because the counter is unwritable.
      await runObserve(testObserve, projectDir, { ECC_OBSERVER_NOSURVIVE_WARN_AFTER: '1' });
    }

    assert.ok(
      !readStartLog(projectDir).includes(WARN_MARKER),
      'an unpersisted streak must not warn, or it would repeat on every tool call'
    );
  } finally {
    cleanupDir(testDir);
  }
}

// A healthy observer clears the streak, so an unrelated one-off crash later on
// does not inherit an old count and warn spuriously.
async function runResetWhenAlive() {
  const { testDir, projectDir, testObserve } = buildSandbox();
  let live = null;
  try {
    fs.writeFileSync(path.join(projectDir, '.observer.pid'), `${deadPid()}\n`);
    await runObserve(testObserve, projectDir, { ECC_OBSERVER_NOSURVIVE_WARN_AFTER: '3' });
    assert.strictEqual(readStreak(projectDir), 1, 'streak should be seeded by the dead observer');

    // A live PID > 1. process.pid is unusable here: in a container Node can be
    // PID 1, which _CHECK_OBSERVER_RUNNING deliberately rejects, so the streak
    // would never reset and this test would fail for the wrong reason.
    live = spawn('sleep', ['30'], { stdio: 'ignore' });
    assert.ok(live.pid > 1, 'expected a live child PID greater than 1');
    fs.writeFileSync(path.join(projectDir, '.observer.pid'), `${live.pid}\n`);
    await runObserve(testObserve, projectDir, { ECC_OBSERVER_NOSURVIVE_WARN_AFTER: '3' });

    assert.strictEqual(
      readStreak(projectDir),
      null,
      'finding the observer alive should clear the non-survival streak'
    );
  } finally {
    if (live) {
      live.kill('SIGKILL');
    }
    cleanupDir(testDir);
  }
}

(async () => {
  if (!isWindows && hasPython) {
    await asyncTest('warns in observer-start.log once the streak reaches the threshold', runWarnsAtThreshold);
    await asyncTest('stays silent while the streak is below the threshold', runSilentBelowThreshold);
    await asyncTest('an all-zero threshold falls back to the default instead of disabling the warning', runRejectsZeroThreshold);
    await asyncTest('a leading-zero threshold is read as decimal, not octal', runLeadingZeroThreshold);
    await asyncTest('an unpersisted streak stays silent instead of warning every call', runSilentWhenCounterUnwritable);
    await asyncTest('a live observer resets the non-survival streak', runResetWhenAlive);
  } else {
    console.log('  - skipping shell-execution tests (requires non-Windows + python3)');
  }

  console.log('\n=== Test Results ===');
  console.log(`Passed: ${passed}`);
  console.log(`Failed: ${failed}`);
  console.log(`Total:  ${passed + failed}`);

  process.exit(failed > 0 ? 1 : 0);
})();