fix(telemetry): bound forward-clock damage to the consent horizon
Sixth review - the first against the interval architecture - verdict: the architecture holds (idempotence, order-independence, 4-process concurrent-writer safety, rollback immunity, format consistency, and a 120-permutation order sweep all verified), with ONE high finding, which I had independently reproduced while the review ran: the FORWARD clock adversary was unhandled, and unlike every other failure mode in this subsystem it failed OPEN. The 'obs' mark is a MAX-upsert - monotonic in the leak direction. One glitched-forward sample (NTP flap reading 2099) while consented dragged last_confirmed_at to 2099; a later revoke stamped closed_at = 2099; the closed window then CONTAINED every refused period that followed. Both the reviewer and I reproduced refused packages becoming gate-eligible. The rollback twin was mutation-tested since round 5; nobody had asked whether the mirror image existed. Two clamps, each covering what the other cannot: - The obs mark advances at most MAX_OBS_ADVANCE_SECONDS (30 days) per call. Honest heartbeats never bind it; a machine off for months catches up in a few hook fires (fail-closed latency only); one insane sample moves the horizon by a bounded step that real time overtakes. - A close is MIN(last_confirmed_at, closing observation's raw stamp). Confirmed-time keeps unobserved gaps out of windows (v1's leak); the raw stamp lets an honest clock at revoke time pull a poisoned horizon back to the true revoke moment. A rolled-back clock at close time only closes earlier - fail-closed. Also from the review: - D2: the data-mark advance in the REAL package writer had no coverage (the harness re-implemented the insert; deleting the production line survived 314 tests). Now driven through create_and_export_package_if_due. - D3: the "don't create ~/.hermes/telemetry for fully-disabled users" skip was dead code - the store constructor creates the directory before the exists() check ran. The probe now checks the default path without constructing; verified empirically on a fresh HERMES_HOME. - Upgrade note in A.4: pre-interval backlog is never transmitted after upgrade (fail-closed; deliberate). New harness scenarios: forward-poison-then-revoke (the leak), and forward-poison-cannot-wedge (the cap). Mutation check: unclamping the close, removing the cap, and removing the real writer's data-mark advance each fail the suite. 273 tests pass; ruff and windows-footguns clean; staging E2E 202.
This commit is contained in:
@@ -403,12 +403,23 @@ Turning sending off also **closes the consent window** — at the last moment
|
||||
consent was actually observed, not at the wall clock. Packages whose periods
|
||||
fall between one window and the next are never transmitted, even if sending
|
||||
is later re-enabled, and this holds for any number of on/off cycles, across
|
||||
hand-edits with no process running, and under a clock that jumps backwards
|
||||
(window opens are clamped above every timestamp already in the store).
|
||||
hand-edits with no process running, and under a clock that jumps in either
|
||||
direction (window opens are clamped above every timestamp already in the
|
||||
store; observation marks advance by a bounded step per call, so one glitched
|
||||
forward sample cannot drag the confirmation horizon years ahead; a close
|
||||
never lands after the closing observation's own clock).
|
||||
Unlike the earlier single moving opt-in date, closing and reopening does NOT
|
||||
discard the still-undelivered backlog from a previous consented window —
|
||||
those packages stay inside their own interval and remain eligible.
|
||||
|
||||
One deliberate upgrade-path consequence: packages exported under the
|
||||
pre-interval consent model (before `send_consent_windows` existed) predate
|
||||
the first recorded window and are therefore never transmitted after an
|
||||
upgrade. This is the fail-closed direction — re-importing the old moving
|
||||
day-stamp to release them would re-import the semantics five review rounds
|
||||
showed to be unsound — and it costs at most the undelivered backlog, never
|
||||
collected data.
|
||||
|
||||
### A.5 Retention
|
||||
|
||||
- **Local:** unchanged — 30 days for successfully exported history, and pending
|
||||
|
||||
@@ -1256,11 +1256,19 @@ def _reconcile_send_consent_once() -> None:
|
||||
reconcile_send_consent,
|
||||
)
|
||||
from hermes_cli.sqlite_util import write_txn
|
||||
from hermes_constants import get_hermes_home
|
||||
|
||||
resolved = resolve_send_config(read_raw_config_readonly() or {})
|
||||
store = SharedMetricsStore()
|
||||
if not resolved.send and not store.database_path.exists():
|
||||
# Probe for an existing store WITHOUT constructing one: the
|
||||
# constructor creates the directory and schema as a side effect,
|
||||
# which round 6 caught making this skip dead code — every
|
||||
# fully-disabled user was getting a ~/.hermes/telemetry directory.
|
||||
default_path = (
|
||||
get_hermes_home() / "telemetry" / "shared_metrics" / "metrics.sqlite3"
|
||||
)
|
||||
if not resolved.send and not default_path.exists():
|
||||
return
|
||||
store = SharedMetricsStore()
|
||||
with store._connection() as connection:
|
||||
with write_txn(connection):
|
||||
reconcile_send_consent(connection, resolved.send)
|
||||
|
||||
@@ -100,6 +100,13 @@ def _isoformat(value: datetime) -> str:
|
||||
return value.astimezone(timezone.utc).isoformat().replace("+00:00", "Z")
|
||||
|
||||
|
||||
def _parse_stamp(value: str) -> datetime:
|
||||
"""Parse a stamp this module itself wrote (Z-suffixed ISO-8601, UTC)."""
|
||||
return datetime.fromisoformat(value.replace("Z", "+00:00")).astimezone(
|
||||
timezone.utc
|
||||
)
|
||||
|
||||
|
||||
@dataclass
|
||||
class SendOutcome:
|
||||
"""What one pass did. Returned for tests and diagnostics."""
|
||||
@@ -164,6 +171,18 @@ def _retry_after_seconds(value: str | None, default: int) -> int:
|
||||
return default
|
||||
|
||||
|
||||
#: Maximum distance one reconcile call can advance the 'obs' mark. Honest
|
||||
#: heartbeats arrive hours apart at most, so the cap never binds in normal
|
||||
#: operation; a machine legitimately off for months catches up in a few
|
||||
#: hook fires (fail-closed latency only). What it bounds is FORWARD clock
|
||||
#: poison: without it, a single glitched sample (NTP flap reading 2099)
|
||||
#: permanently drags the mark — and with it every window open and every
|
||||
#: confirmation horizon — decades ahead, which round 6 reproduced as a
|
||||
#: refused-data leak. Capped, one insane sample moves the mark at most
|
||||
#: this far, and real time overtakes it again.
|
||||
MAX_OBS_ADVANCE_SECONDS = 30 * 24 * 3600
|
||||
|
||||
|
||||
def reconcile_send_consent(
|
||||
connection: sqlite3.Connection,
|
||||
send_enabled: bool,
|
||||
@@ -182,9 +201,15 @@ def reconcile_send_consent(
|
||||
Timestamp discipline (each rule is load-bearing; see the validation
|
||||
harness in tests/hermes_cli/test_shared_metrics_consent_windows.py):
|
||||
|
||||
- The 'obs' mark advances to every observation stamp, monotonically.
|
||||
An open window's ``last_confirmed_at`` follows it: consent is asserted
|
||||
only for time that was actually observed.
|
||||
- The 'obs' mark advances to every observation stamp, monotonically —
|
||||
but by at most ``MAX_OBS_ADVANCE_SECONDS`` per call. Unbounded, the
|
||||
mark is monotonic in the LEAK direction: one glitched-forward sample
|
||||
would drag ``last_confirmed_at`` decades ahead, a later close would
|
||||
stamp that horizon, and the closed window would contain every future
|
||||
refused period (reproduced in round 6). Bounded, a poisoned sample
|
||||
costs at most one cap's width, and real time overtakes it.
|
||||
An open window's ``last_confirmed_at`` follows the mark: consent is
|
||||
asserted only for time that was actually observed.
|
||||
- A close is stamped at ``last_confirmed_at`` — never "now" — so an
|
||||
unobserved gap (hand-edited config, machine off for 90 days) is never
|
||||
inside a window and fails closed.
|
||||
@@ -193,6 +218,16 @@ def reconcile_send_consent(
|
||||
make the new window adjacent to the previous close.
|
||||
"""
|
||||
stamp = _isoformat(now or _utc_now())
|
||||
raw_stamp = stamp # pre-cap observation time, used to clamp closes
|
||||
previous_obs = connection.execute(
|
||||
"SELECT stamp FROM consent_marks WHERE name = 'obs'"
|
||||
).fetchone()
|
||||
if previous_obs is not None:
|
||||
ceiling = _isoformat(
|
||||
_parse_stamp(str(previous_obs[0]))
|
||||
+ timedelta(seconds=MAX_OBS_ADVANCE_SECONDS)
|
||||
)
|
||||
stamp = min(stamp, ceiling)
|
||||
connection.execute(
|
||||
"""
|
||||
INSERT INTO consent_marks(name, stamp) VALUES ('obs', ?)
|
||||
@@ -226,10 +261,22 @@ def reconcile_send_consent(
|
||||
(obs, open_row[0]),
|
||||
)
|
||||
elif open_row is not None:
|
||||
# Close at the last CONFIRMED moment, but never after the closing
|
||||
# observation's own raw stamp. The two clamps serve different
|
||||
# adversaries and both are load-bearing:
|
||||
# - min with last_confirmed_at: an unobserved gap (machine off,
|
||||
# hand-edited config) is never asserted as consented (v1's leak).
|
||||
# - min with the RAW stamp (pre-cap, pre-MAX): if last_confirmed_at
|
||||
# was poisoned by a glitched-forward sample, an honest clock at
|
||||
# revoke time pulls the close back to the true revoke moment, so
|
||||
# the refused era that follows falls OUTSIDE the closed window
|
||||
# (round 6's D1 leak). A rolled-back clock at close time only
|
||||
# closes EARLIER — fail-closed.
|
||||
connection.execute(
|
||||
"UPDATE send_consent_windows SET closed_at = last_confirmed_at"
|
||||
"UPDATE send_consent_windows"
|
||||
" SET closed_at = MIN(last_confirmed_at, ?)"
|
||||
" WHERE rowid = ?",
|
||||
(open_row[0],),
|
||||
(raw_stamp, open_row[0]),
|
||||
)
|
||||
|
||||
|
||||
|
||||
@@ -131,6 +131,62 @@ class TestRefusedWindowIsNeverReleased:
|
||||
|
||||
|
||||
class TestClockAdversaries:
|
||||
def test_forward_poison_then_revoke_releases_nothing(self, store):
|
||||
"""Round 6 D1: one glitched-forward sample must not defeat a close.
|
||||
|
||||
Unfixed, the poisoned obs mark dragged last_confirmed_at to 2099, a
|
||||
later revoke stamped closed_at = 2099, and the closed window then
|
||||
CONTAINED every refused period that followed — all 8 refused
|
||||
packages became eligible. The close now clamps to the closing
|
||||
observation's own raw stamp, so an honest clock at revoke time pulls
|
||||
the window back to the true revoke moment.
|
||||
"""
|
||||
_observe(store, True, dt(0))
|
||||
_observe(store, True, datetime(2099, 1, 1, tzinfo=timezone.utc))
|
||||
_observe(store, False, dt(1)) # honest clock at revoke
|
||||
for n in range(2, 10):
|
||||
_add(store, f"REFUSED-{n}", ts(days=n), ts(days=n, hours=2))
|
||||
|
||||
leaked = [p for p in _eligible(store) if p.startswith("REFUSED")]
|
||||
assert not leaked, f"poisoned horizon released refused data: {leaked}"
|
||||
|
||||
def test_forward_poison_cannot_wedge_consent_forever(self, store):
|
||||
"""The obs-advance cap bounds the damage of one insane sample.
|
||||
|
||||
Uncapped, a 2099 sample would clamp every future window open at
|
||||
2099, suppressing consented data for decades (fail-closed but
|
||||
permanent). Capped, the mark moves at most MAX_OBS_ADVANCE_SECONDS
|
||||
past its previous value, so honest time overtakes it.
|
||||
"""
|
||||
from hermes_cli.observability.shared_metrics_sender import (
|
||||
MAX_OBS_ADVANCE_SECONDS,
|
||||
)
|
||||
|
||||
_observe(store, True, dt(0))
|
||||
_observe(store, True, datetime(2099, 1, 1, tzinfo=timezone.utc))
|
||||
with store._connection() as connection:
|
||||
stamp = connection.execute(
|
||||
"SELECT stamp FROM consent_marks WHERE name = 'obs'"
|
||||
).fetchone()[0]
|
||||
ceiling = ts(days=MAX_OBS_ADVANCE_SECONDS // 86_400)
|
||||
assert stamp <= ceiling, (
|
||||
f"one glitched sample advanced the mark unboundedly: {stamp}"
|
||||
)
|
||||
|
||||
# Consented data from shortly after the cap horizon still flows once
|
||||
# honest observations catch the marks up.
|
||||
horizon_days = MAX_OBS_ADVANCE_SECONDS // 86_400
|
||||
_add(
|
||||
store,
|
||||
"post-glitch",
|
||||
ts(days=horizon_days + 1),
|
||||
ts(days=horizon_days + 1, hours=4),
|
||||
)
|
||||
_observe(store, True, dt(days=horizon_days + 2))
|
||||
assert "post-glitch" in _eligible(store), (
|
||||
"consent wedged after a forward glitch"
|
||||
)
|
||||
|
||||
def test_rollback_at_re_enable_releases_nothing(self, store):
|
||||
"""Round 5 D2: the data mark clamps opens above existing packages."""
|
||||
_observe(store, True, dt(0))
|
||||
@@ -201,6 +257,39 @@ class TestReconcilerProperties:
|
||||
).fetchone()[0]
|
||||
assert stamp == ts(5), f"obs mark moved backwards: {stamp}"
|
||||
|
||||
def test_the_real_package_writer_advances_the_data_mark(self, store):
|
||||
"""Round 6 D2: the harness's _add re-implements the data-mark insert,
|
||||
so deleting the advance from the REAL writer survived 314 tests.
|
||||
This drives the production exporter instead.
|
||||
"""
|
||||
from datetime import date, timedelta as _td
|
||||
|
||||
yesterday = (date.today() - _td(days=1)).isoformat()
|
||||
with store._connection() as connection:
|
||||
with write_txn(connection):
|
||||
connection.execute(
|
||||
"INSERT INTO counter_aggregates("
|
||||
" period_start, metric_name, hermes_version, os_family,"
|
||||
" architecture, install_method, dimensions_json, value,"
|
||||
" packaged_value"
|
||||
") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)",
|
||||
(
|
||||
yesterday, "hermes.client.active", "0.0.0-test",
|
||||
"macos", "arm64", "git", "{}", 1, 0,
|
||||
),
|
||||
)
|
||||
|
||||
exported = store.create_and_export_package_if_due()
|
||||
assert exported, "the generator was expected to export yesterday's period"
|
||||
|
||||
with store._connection() as connection:
|
||||
row = connection.execute(
|
||||
"SELECT stamp FROM consent_marks WHERE name = 'data'"
|
||||
).fetchone()
|
||||
assert row is not None and row[0] >= yesterday, (
|
||||
"the production package writer did not advance the data mark"
|
||||
)
|
||||
|
||||
def test_the_gate_is_read_only(self, store):
|
||||
_observe(store, True, dt(0))
|
||||
before = _windows(store)
|
||||
|
||||
@@ -315,8 +315,18 @@ class TestConsentWindows:
|
||||
)
|
||||
from hermes_cli.sqlite_util import write_txn
|
||||
|
||||
# Lay the store out exactly as production does, under a redirected
|
||||
# HERMES_HOME: the boot reconciler probes the default path (without
|
||||
# constructing the store — the constructor creates directories), so
|
||||
# the probe and the store must agree the way they do in production.
|
||||
home = tmp_path / "home"
|
||||
monkeypatch.setattr(
|
||||
"hermes_constants.get_hermes_home", lambda: home
|
||||
)
|
||||
root = home / "telemetry" / "shared_metrics"
|
||||
store = SharedMetricsStore(
|
||||
database_path=tmp_path / "m.db", outbox_directory=tmp_path / "o"
|
||||
database_path=root / "metrics.sqlite3",
|
||||
outbox_directory=root / "outbox",
|
||||
)
|
||||
# A consent window is open from an earlier consented era.
|
||||
with store._connection() as connection:
|
||||
|
||||
Reference in New Issue
Block a user