Skip to content

Install: service reports success on failure, cross-repo requirement order, heartbeat wait too short #3683

Open

Description

@trissim

Three defects found installing #3677 on 2026-10-30. None is fixed yet.

  1. The install service reports success when the install failed. agent-comms-install-*.service ended Result=success / ExecMainStatus=0 on both 287da7b (ValueError: batrachian-toad declares 0 agent_comms.runtime_preparation entry points) and 9345445 (install: refused). A readiness signal that lies: anyone reading the service state believes a dead install worked.

  2. A Core PR can require something a sibling repo has not landed. e951709 made Core demand a Toad entry point while toad#1357 was open with red checks, and main could not install until Hotfix: stop requiring a Toad preparation Toad does not declare yet #3682 removed the requirement. toad#1357 must restore ToadPackage.preparations together with its entry point. The merge order is not declared anywhere.

  3. The installer's heartbeat wait is shorter than a heartbeat under load. Install of 9345445 refused at commander_heartbeat: no ordinary completion since service restart 1793355719. service_passes.json shows the pass completed at 1793355924, 205 s later, with failing: {}, at load 93. The new runtime was already published, so the refusal changed nothing except reporting failure on a working install. The pending list also names codex-greentext, which is retired.

🤖 Generated with Claude Code

https://claude.ai/code/session_01XbFMSpSd8zQxyozgEV2Re7

Activity

  1. trissim commented on Oct 30, 2026

    @trissim
    ContributorAuthor

    Correction to item 3: I blamed machine load, and that was wrong. The 93 is the board's work-owed figure; CPU load average was about 11. The pass itself is slow: completions at 1793355924 and 1793356229, about 305 s apart, against the 180 s limit behind missed_heartbeat. So a working heartbeat raises 'I have to tell you it's hung?' on every pass, and the installer's wait is too short for the same reason. The fix is to profile the pass, not lengthen the wait.

  2. trissim commented on Oct 30, 2026

    @trissim
    ContributorAuthor

    Item 2 shape, from the side that broke it (my fork admin-merged #3650): the merge path didn't skip anything that would have caught it. #3650's checks were green because Core's CI never runs the Toad half. So a pair check in queue_bypass.py keyed on PR numbers in the body is the wrong owner; it's a string convention restating a dependency the packages already declare.

    The owner is the requirement itself: ToadPackage.preparations (installer/runtime_resolution.py) is the declaration that Core demands a Toad entry point. Core's required CI should run the same PreparePackageProbe against batrachian-toad at origin/main, the version the installer resolves. Then a Core PR demanding something Toad hasn't landed goes red on its own head, every merge path reads that red, and the merge order comes from the check, not from anyone remembering it. Admin merges stay possible for hotfixes, but the hook's ok-verdict requirement plus a red required check makes "ok on a red cross-repo probe" a visible decision rather than an accident.

    🤖 Generated with Claude Code

    https://claude.ai/code/session_01XbFMSoWgC3ZwKzjT4SwMDu

  3. trissim commented on Oct 30, 2026

    @trissim
    ContributorAuthor

    Heartbeat pass sampling, not conclusive. I sampled the connector's child processes every 0.5 s for 90 s, during which the pass ran well past the 180 s limit. A child was visible in about a third of samples: mostly git log -1 --extended-regexp (18 of 59 lines) and gh api graphql (18), mostly against the main checkout. So subprocesses are not obviously the whole cost: the connector sits at about 47% CPU and most samples show no child, which points at Python in-process, but that is unmeasured. py-spy is blocked by ptrace_scope=1, so naming the owner needs: sudo py-spy record --pid $(systemctl --user show agent-comms-connector.service -p MainPID --value) --duration 300 --rate 50 --format raw -o /home/ts/.cache/agent-scratch/claude-nra/heartbeat-profile.txt. claude-nra holds this.

  4. trissim commented on Oct 30, 2026

    @trissim
    ContributorAuthor

    Retracting item 1: I was wrong, and the service does not lie. The journal shows both units ended status=1/FAILURE, Failed with result 'exit-code'. I read systemctl show after the transient unit had unloaded (LoadState=not-found), and it prints a default Result=success for a unit that no longer exists. Trick: read a finished transient unit with journalctl, never systemctl show. Items 2 and 3 stand; claude-nra holds both. Item 3 needs the py-spy profile from the comment above.

  5. trissim commented on Oct 30, 2026

    @trissim
    ContributorAuthor

    Item 3 evidence, from reading the source and the 09:07 install. No profile numbers yet; one is running.

    • Restated fact: HeartbeatSilent.seconds = 180 (commander/standing.py) calls a pass hung, while CommanderHeartbeat.pass_duration = 270 (commander_heartbeat.py:68) declares 270 s the longest normal pass. So MissedHeartbeat can fire on a pass the code itself calls normal. Passes finished 08:54:16 and 08:58:30, 254 s apart.
    • Install cost: install 2f6728e restarted the units, then sat in ProbePhase: commander_heartbeat from 09:08:38, waiting for a pass on the new build. Silent log, no failure. My own STALLED watch fired on it at 182 s.
    • Raising 180 only hides this. The defect is the 4-minute pass; the alarm limit should then derive from pass_duration, not restate it.
  6. trissim commented on Oct 30, 2026

    @trissim
    ContributorAuthor

    Correction to my P1023 report 44c97cbb7a09: I said registry_document.decode_row costs 35.5 s and that no order holds it. Wrong. A second profile puts it at 5.9 s (5397 decodes, not 26816); the first number came from one cold run and I reported it as a defect. Do not order on it. What held across both runs: git 59.5 s and 57.3 s, about 2100 calls, of 198 s and 159 s read time, so 30-36%. P1018 is aimed at the largest repeatable cost. Still true: it cannot fix the pass alone, because read phases are 159-198 s under the profiler and pass_body was never measured. Also wrong along the way: I guessed the registry was re-read per caller; snapshot costs 0.3 s in total.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions