Skip to content

bug(service): service install exits non-zero when a committed registration is merely slow to become live #1701

Description

@AlexStocks

Describe the bug

powercontext service install gives the Server 60 seconds to become live and then reports a hard failure — exit code 1, PowerContext personal service installation failed: ... — even though the registration was committed before the wait started and the Server is on its way up in that same moment.

src/powercontext/service/controller.py:57 fixes the budget:

_START_TIMEOUT_SECONDS = 60.0

and controller.py:114-119 turns "still not live after the budget" into a post-commit error:

final_probe = self._wait_until_live(definition.endpoint)
if final_probe.state is not ProbeState.LIVE:
    raise self._post_commit_error(
        f"the personal service was registered but did not become live: {final_probe.detail}; "
        f"inspect {self._adapter.log_location(definition) or 'the native service logs'}"
    )

I reproduced this on a build that already contains #1694, so the 60 second budget is short independently of the scheduling-policy bug:

launchd job start → live vs 60 s budget
cold bytecode cache (0 / 8740 modules compiled) 92 s exceeded by 32 s
warm bytecode cache 55 s 92 % of the budget consumed

The warm figure is the more uncomfortable one: on the same machine, a plain restart already spends 50 of the 60 seconds inside the interpreter's import phase — uvicorn does not log Started server process until 50 seconds after launchd starts the process. The budget is therefore almost entirely consumed by work that happens before the Server can even begin listening.

Steps to reproduce

Environment where this was measured: macOS 12.7.6, Intel x86_64, LaunchAgent com.oceanbase.powercontext.

  1. Confirm the build under test contains fix(service): avoid background throttling on macOS #1694. Here git log -1 is cca04993 (94297e1e / fix(service): avoid background throttling on macOS #1694 is an ancestor), installed version 1.1.1.dev5+gcca049938.

  2. Install a fresh tool environment without --compile-bytecode, which is what every documented install command does:

$ uv tool install --force "/path/to/powercontext[cli,server]"
$ find ~/.local/share/uv/tools/powercontext/lib/python3.12/site-packages -name '*.pyc' | wc -l
0
$ find ~/.local/share/uv/tools/powercontext/lib/python3.12/site-packages -name '*.py'  | wc -l
8740

So all 8740 modules are compiled on first import, and the very first import is the one service install is waiting on.

  1. Stop the service, then run the install while polling the endpoint once every two seconds:
$ launchctl bootout gui/$(id -u)/com.oceanbase.powercontext
$ powercontext service install --env-file ~/powercontext-config/.env   # poll /v1/capabilities in parallel

Observed timeline:

moment clock delta
command starts 18:49:14 —
launchd job starts (launchctl bootstrap + kickstart returned) 18:49:58 +44 s — the CLI's own cold import, before the job exists
install gives up, exits 1 18:51:04 +110 s
endpoint first answers 200 18:51:30 +92 s from job start, +136 s from command start
  1. Verify the scheduling fix really is in effect, so this is not fix(service): avoid background throttling on macOS #1694 being absent:
$ /usr/libexec/PlistBuddy -c "Print :ProcessType" ~/Library/LaunchAgents/com.oceanbase.powercontext.plist
Standard

The install rewrote the definition from Background to Standard exactly as #1694 intends. The cold start still took 92 seconds.

  1. Control experiment on the same machine, same build, warm cache:
$ launchctl kickstart -k gui/$(id -u)/com.oceanbase.powercontext
# job start 18:52:20 → endpoint answers 200 at 18:53:15  => 55 s

and the Server log puts the import phase in plain sight:

18:53:10 INFO uvicorn Started server process [96077]      # 50 s after the job started
18:53:13 INFO powercontext.server.factory PowerContext Server is ready
18:53:15 INFO powercontext.server.access ... request completed

Expected behavior

A committed registration that is merely slow should not be reported the same way as a registration that genuinely failed to start. Options, roughly in order of my preference:

  • Distinguish the two outcomes. When the definition was committed and the manager reports the job running, do not exit non-zero and do not say "installation failed" — say "registered; the Server has not answered on http://127.0.0.1:8000 yet, check powercontext service status and <log dir>". Everything needed is already there: src/powercontext/service/cli.py:81-84 prints the full status block immediately after the error, and in my run that block already said definition: current, manager ownership: owned, manager: active. Only the exit code and the word "failed" are wrong. Thirty seconds later powercontext service status reported server liveness: live.
  • Warm the bytecode cache during install, so the first start does not pay for compiling 8740 modules inside the readiness window.
  • Raise or make configurable the budget. _START_TIMEOUT_SECONDS is a module constant with no override, while the work it bounds is hardware-dependent. This machine is old, and that is precisely the point: a fixed wall-clock budget will always be wrong for some supported machines, whereas "was the native job actually started" is not hardware-dependent at all.
  • Document --compile-bytecode: uv tool install --compile-bytecode (or UV_COMPILE_BYTECODE=1) compiles at install time and removes the cold cache. If a docs line is the intended answer, this issue can be closed as documented — the exit-status/error-contract point above still stands on its own.

Actual behavior

Verbatim output of the failing install:

PowerContext personal service installation failed: the personal service was registered but did not become live: cannot reach http://127.0.0.1:8000; inspect ~/Library/Application Support/powercontext/logs
support: supported
registration: installed
definition: current
manager ownership: owned
manager: active
server liveness: unreachable (http://127.0.0.1:8000)
logs: ~/Library/Application Support/powercontext/logs
detail: cannot reach http://127.0.0.1:8000
action: inspect the native service logs, then run `powercontext service install`

The status block contradicts the headline in the same output, and the suggested action — run service install again — is wrong: the service came up on its own 26 seconds later, with no intervention, and stayed up.

For context, the same machine previously showed a much worse version of this symptom. Before #1694 the first start did not finish in five minutes at all: the launchd job was alive but progressing at roughly 4 % CPU, and interrupting it to print a traceback showed importlib._bootstrap_external._write_atomic — the bytecode write. Compiling the same tree in the foreground took 66 seconds. #1694 removed that specific pathology (I re-measured: ProcessType migrates to Standard automatically on install, which is a nice touch), but the budget it was never the cause of is still being exceeded.

Environment

  • PowerContext version: 1.1.1.dev5+gcca049938 (local master at cca04993, containing 94297e1e / fix(service): avoid background throttling on macOS #1694)
  • Python version: 3.12.13 (uv tool environment, ~/.local/share/uv/tools/powercontext)
  • OS: macOS 12.7.6, Intel x86_64, launchd gui/<uid>/com.oceanbase.powercontext

Additional context

  • Verified independently of the scheduling question: the contradictory wording and the exit code come from controller.py:114-119 plus cli.py:79-89, neither of which fix(service): avoid background throttling on macOS #1694 touches.
  • _wait_until_live only keeps waiting while the probe reports UNREACHABLE (controller.py:341-348), so the whole budget is spent on process start-up; the port opens after the import phase. That makes the budget effectively "interpreter + 2301 module imports + Server boot", not "time to answer".
  • The cold pre-flight import of the CLI itself cost 44 seconds before the launchd job was even created. That is a separate, purely user-facing cost of the same root cause, and it is the strongest argument for documenting --compile-bytecode.
  • Import hotspots, from python -X importtime -c "from powercontext.server import cli" (2301 modules, 28.8 s cumulative self time): powercontext.http._generated.operations 2846 ms, powercontext.http._generated.models 2437 ms, mcp.types 1019 ms, fastapi.openapi.models 789 ms, proxytypes 652 ms. The two generated OpenAPI modules are eagerly imported and together outweigh every third-party package.
  • Checked every install command in the repository: they all read uv tool install --force "powercontext[cli,server] @ git+https://github.com/oceanbase/powercontext.git@master" (docs/en/docs/develop/api-quickstart.md:19, docs/en/docs/workflows/codex-workflow.md:59, docs/en/docs/integrations/{workbuddy,dsh,langchain,openclaw,hermes}.md), none passes --compile-bytecode. The cold first start is what every document-following user gets, not an artifact of my particular install.
  • Unrelated note, not a defect claim: the repository carries two tag lineages simultaneously — refs/tags/v1.1.0…v1.1.7 from the pre-rewrite history alongside the current powercontext-v* series. Both exist on origin, so git tag --sort=-v:refname | head reports v1.1.7 as the newest tag while the current release line is powercontext-v1.1.0. A line in the release/version docs would help; I am not suggesting that published tags be deleted.
  • Happy to submit a PR. I would start with the smallest change — treating a committed-but-not-yet-live registration as a non-fatal, clearly worded outcome — if a maintainer confirms that is the intended contract.
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

    bugSomething isn't working

    Type

    No type

    Projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions