perf(cli): publish off-thread so logging a meal returns immediately

`diet-guard log ...` blocked for ~15.5s after every meal. The publish itself
has to happen -- until it lands the phone still believes the slot is unlogged
and nags for it -- but only ~2.5s of that is the 293KB push the phone needs;
the rest is pulling peers' banks, which publishing does not require.

The local write is already durable before the publish starts, so the worst
case is a late publish, which is the trade `_sync_events` already documents
for the event-driven model. Moving it to a worker thread lets the caller
print and return at once. Measured: 15.5s -> 2ms before the prompt comes back.

The thread is deliberately non-daemon: the CLI's output is already flushed,
so the process lingers only as long as the push, and the publish is never
killed halfway. A failure still surfaces, via a callback the caller supplies,
just after its own output rather than in the middle of it.

Deliberately NOT applied to the gate. `diet-guard-gate.service` is
`Type=oneshot`, so systemd reaps the unit the moment the main thread exits
and a background publish would be killed mid-push. The gate keeps calling
`publish_after_log` and waiting, which is correct there -- its publish
already runs after the window is gone, where nobody is waiting on it.

`conftest._isolate_state` follows the rename to
`publish_after_log_detached`; without that every meal-logging test would
reach the network through a newly unpatched seam. Verified with
`scripts/check_patch_targets.py` and by timing the real command against a
temporary data dir, never the live log.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01LJ5YnA3CERitQ57HjMu2Qz
This commit is contained in:
Krzysztof Rudnicki 2026-08-21 13:22:26 +02:00
parent 6258b35f88
commit 8871408b5b
6 changed files with 97 additions and 10 deletions

View File

@ -2,7 +2,7 @@ name: diet_guard_app
description: "Companion phone app for diet_guard: log meals on the go."
publish_to: 'none'
version: 1.0.43+1
version: 1.0.44+1
environment:
sdk: ^3.12.2

View File

@ -22,7 +22,7 @@ from diet_guard._portions import DEFAULT_ITEM_GRAMS, estimate_unit_grams
from diet_guard._resolve import ManualMacros, resolve_nutrition
from diet_guard._slots import slot_for_log
from diet_guard._state import log_meal, now_local
from diet_guard._sync_events import publish_after_log
from diet_guard._sync_events import publish_after_log_detached
if TYPE_CHECKING:
from collections.abc import Callable
@ -156,8 +156,15 @@ def cmd_ate(
)
# Publish straight away rather than waiting for a periodic tick: until this
# lands, the phone still believes this slot is unlogged and will nag for it.
reason = publish_after_log()
if reason is not None:
emit(f"logged locally, not yet published ({reason}).")
#
# On a background thread, though: the full tick measures ~15.5s and this is
# an interactive command, so blocking the terminal on it after every meal
# is the whole complaint. The local write above is already durable, so the
# worst case is a late publish -- the trade `_sync_events` documents. The
# thread is non-daemon, so the process waits for the push at exit even
# though the user already has their output.
publish_after_log_detached(
lambda reason: emit(f"logged locally, not yet published ({reason})."),
)
print_summary()
return 0

View File

@ -28,6 +28,11 @@ from __future__ import annotations
from importlib import import_module
import logging
import sys
import threading
from typing import TYPE_CHECKING
if TYPE_CHECKING:
from collections.abc import Callable
_logger = logging.getLogger(__name__)
@ -62,3 +67,35 @@ def publish_after_log() -> str | None:
if reason is not None:
_logger.info("post-log sync skipped: %s", reason)
return reason
def publish_after_log_detached(on_failure: Callable[[str], None]) -> None:
"""Publish on a background thread, returning immediately.
For the *interactive* CLI, where blocking the terminal is the problem: the
full tick measures ~15.5s, of which only ~2.5s is the push the phone
actually needs. The local write is already durable by the time this is
called, so the worst case is a late publish -- exactly the trade
:func:`publish_after_log` already documents.
**Not for the gate.** ``diet-guard-gate.service`` is ``Type=oneshot``, so
systemd reaps the unit as soon as the main thread exits and a daemon
thread would be killed mid-push. The gate keeps calling
:func:`publish_after_log` and waiting for it.
The thread is non-daemon precisely so the interpreter waits for it at exit:
the CLI's output is already flushed, so the user sees their result at once
while the process lingers only as long as the push takes.
Args:
on_failure: Called with a reason if the publish could not complete.
Runs on the worker thread, after the caller has printed and
returned, so it must not touch the caller's output ordering.
"""
def _publish() -> None:
reason = publish_after_log()
if reason is not None:
on_failure(reason)
threading.Thread(target=_publish, daemon=False).start()

View File

@ -152,7 +152,7 @@ def _isolate_state(tmp_path: Path) -> Iterator[None]:
# path that has nothing to do with what it is asserting. Patched at the
# *call sites* rather than on `_sync_events`, so a test that imports
# `publish_after_log` directly still exercises the real helper.
patch("diet_guard._cli_log.publish_after_log", return_value=None),
patch("diet_guard._cli_log.publish_after_log_detached", return_value=None),
patch("diet_guard._cli_gate.publish_after_log", return_value=None),
patch("diet_guard._mcp.publish_after_log", return_value=None),
# The gate's pre-lock refresh is a *second*, independent network

View File

@ -117,23 +117,24 @@ class TestAte:
assert "logged:" in capsys.readouterr().out
def test_publishes_after_logging(self) -> None:
"""The meal is published immediately, not left for a periodic tick."""
"""Publishing starts immediately; off-thread, so it is not awaited."""
write_budget(2000)
with (
patch.object(_cli_log, "resolve_nutrition", return_value=_NUT),
patch.object(_cli_log, "publish_after_log", return_value=None) as publish,
patch.object(_cli_log, "publish_after_log_detached") as publish,
):
assert main(["ate", "big mac"]) == 0
publish.assert_called_once_with()
publish.assert_called_once()
def test_sync_outage_still_logs_locally(
self, capsys: pytest.CaptureFixture[str]
) -> None:
"""A failed publish reports itself without failing the local log."""
write_budget(2000)
fail = {"side_effect": lambda cb: cb("no token")}
with (
patch.object(_cli_log, "resolve_nutrition", return_value=_NUT),
patch.object(_cli_log, "publish_after_log", return_value="no token"),
patch.object(_cli_log, "publish_after_log_detached", **fail),
):
assert main(["ate", "big mac"]) == 0
out = capsys.readouterr().out

View File

@ -8,6 +8,7 @@ reaches the genuine helper (see ``conftest._isolate_state``).
from __future__ import annotations
import logging
import threading
from typing import TYPE_CHECKING
from unittest.mock import patch
@ -52,3 +53,44 @@ class TestPublishAfterLog:
):
publish_after_log()
assert "boom" in caplog.text
class TestPublishAfterLogDetached:
"""The CLI's non-blocking publish."""
def test_runs_the_publish_off_thread(self) -> None:
"""The caller must not wait ~15.5s for the tick to finish."""
done = threading.Event()
def _publish() -> None:
done.set()
with patch.object(_sync_events, "publish_after_log", side_effect=_publish):
_sync_events.publish_after_log_detached(lambda _reason: None)
assert done.wait(timeout=5), "publish never ran"
def test_reports_a_failure_through_the_callback(self) -> None:
"""A publish outage still surfaces, just after the caller returned."""
seen: list[str] = []
finished = threading.Event()
def _record(reason: str) -> None:
seen.append(reason)
finished.set()
with patch.object(_sync_events, "publish_after_log", return_value="no token"):
_sync_events.publish_after_log_detached(_record)
assert finished.wait(timeout=5), "callback never fired"
assert seen == ["no token"]
def test_stays_quiet_on_success(self) -> None:
"""Nothing to report means the callback is never called."""
calls: list[str] = []
with patch.object(_sync_events, "publish_after_log", return_value=None):
_sync_events.publish_after_log_detached(calls.append)
for thread in threading.enumerate():
if thread is not threading.current_thread():
thread.join(timeout=5)
assert calls == []