diff --git a/family/documents/vault-sync/2026-09-16-silent-tick-clusters.md b/family/documents/vault-sync/2026-09-16-silent-tick-clusters.md index fd344046..76ce9a64 100644 --- a/family/documents/vault-sync/2026-09-16-silent-tick-clusters.md +++ b/family/documents/vault-sync/2026-09-16-silent-tick-clusters.md @@ -1,60 +1,82 @@ --- -tags: [vault, git, sync, cron, incident] +tags: [vault, git, sync, cron, incident, correction] date: 2026-09-16 --- -# 2026-09-16 — молчащие тики идут кластерами 4–5 подряд +# 2026-09-16 — перепроверка молчащих тиков: «кластеры» оказались артефактом метода -## Итог ручного прогона (01:00 UTC) +Утренняя находка этого дня («молчащие тики идут кластерами 4–5 подряд», +16:55→17:15 и 23:45→00:00) **опровергнута** при перепроверке 13:25 UTC. -```bash -cd /opt/data && bash /opt/data/sync-vault.sh >> /tmp/vault-sync.log 2>&1 -``` +## Что было не так -Exit 0, «Pushed ✓» по всем трём фазам. Фаза 1 подтянула правки Eagle (коммит `8fe2e51`: -`family/how-to/ha-automations.md`, `family/how-to/home-automation.md`, -`family/tech/ha-registry-operations.md`, `family/tech/zigbee-t610-z2m-i-zha.md`). +Первый скрипт сверки сравнивал **минуту** тика из `executions.db` (`claimed_at[:16]`) +с минутой timestamped-строки `[syncthing] Pushed ✓` в логе. -Проверка: `/vault`, `/obsidian-syncthing` и bare — все на `8fe2e51`, `git status --porcelain` пуст -(жёсткие симлинки на /.obsidian в sparse checkout — норма). +Скрипт стартует внутри тика не мгновенно: при `claimed_at = 16:55:55` первая строка +лога появляется в `16:56:01` — минута не совпадает, и «здоровый» тик ложно попадал +в молчащие. Все тики из обоих «кластеров» скрипт **вызывал**, их строки в логе есть: +`16:56:01`, `17:01:00`, `17:06:04`, `17:11:02`, `23:46:02`, `23:51:01`, `23:56:02`, `00:01:03`. -## Находка: молчащие тики группируются +Фактический сдвиг `claimed_at` → запись лога в окне 12–60 с; иногда он переходит +через границу минуты — именно это и порождало ложные «пропуски». -Метод: сверка `/tmp/vault-sync.log` с `/opt/data/cron/executions.db` по job_id `29851c413903`, -окно = с начала текущего лога (2026-09-15 11:35:19 — лог был обрезан при рекреации контейнера) -до 2026-09-16 01:00. +## Корректный метод -- запусков: 161, из них **11 (6,8 %) `completed` без единой строки в логе** (~19 с и меньше) -- это тот же режим отказа, что описан 2026-09-14: LLM-раунд отвечает текстом, bash не вызывается -- **новое:** пропуски идут не по одному, а кластерами: - - 2026-09-15 16:55 → 17:15 — 5 подряд (25 мин без синка) - - 2026-09-15 23:45 → 00:00 — 4 подряд (20 мин без синка) - - одиночные: 13:55, 22:50 +Сопоставлять по **окну**, а не по минуте: строка `[syncthing]` должна попадать +в `[claimed_at − 45 с; finished_at + 90 с]`. Метод замера 2026-09-14 +(окно 300 с) был корректен — цифра 6,6 % за те сутки под сомнение не ставится. -Разрывы >10 мин в логе поэтому надо читать как «тик выполнился, но скрипт не вызван», а не как -«диспетчер не запустил задачу». Данные не теряются: git-синк идемпотентен, следующий удачный тик -догоняет всё. +## Фактические цифры (окно текущего лога) -Скрипт сверки (лог × executions.db, считает кластеры): +Окно 2026-09-15 11:35:19 → 2026-09-16 13:25 UTC (начало лога — рекреация контейнера): +**312 тиков, 3 молчащих (0,96 %)**: + +| тик (UTC) | dur | +|---|---| +| 2026-09-15 13:55 | 5,8 с | +| 2026-09-15 22:50 | 7,4 с | +| 2026-09-16 12:10 | 6,1 с | + +Режим отказа реален (LLM-раунд завершается без вызова bash, `status=completed`, ~6 с), +но встречается ~1 раз на 100 тиков, а не 1 на 15. 10-минутный разрыв в логе = +один молчащий тик; разрывов 20–25 мин за окно нет. + +## Скрипт сверки (окно, а не минута) ```bash python3 - <<'EOF' -import sqlite3,re -from datetime import datetime +import sqlite3, re +from datetime import datetime, timedelta c=sqlite3.connect('file:/opt/data/cron/executions.db?mode=ro',uri=True) rows=c.execute("select claimed_at,finished_at,status from executions where job_id='29851c413903' order by claimed_at").fetchall() log=open('/tmp/vault-sync.log',encoding='utf-8',errors='replace').read() -log_start=datetime.strptime(re.search(r'\[(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d)\]',log).group(1),'%Y-%m-%d %H:%M:%S') -ticks=set(re.findall(r'\[(\d{4}-\d\d-\d\d \d\d:\d\d):\d\d\] \[syncthing\] Pushed',log)) -sel=[r for r in rows if datetime.fromisoformat(r[0]).replace(tzinfo=None)>=log_start] -miss=[r[0][:16].replace('T',' ') for r in sel if r[2]=='completed' and r[0][:16].replace('T',' ') not in ticks] -print('runs',len(sel),'silent',len(miss)) -for m in miss: print(' ',m) +P=lambda s: datetime.fromisoformat(s).replace(tzinfo=None) +pat=r'\[(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d)\] \[syncthing\] Pushed' +logts=[datetime.strptime(m,'%Y-%m-%d %H:%M:%S') for m in re.findall(pat,log)] +start=min(logts) +sel=[r for r in rows if P(r[0])>=start-timedelta(minutes=7)] +silent=[] +for cl,fin,st in sel: + if st!='completed' or not fin: continue + a,b=P(cl),P(fin) + if not any(a-timedelta(seconds=45)<=t<=b+timedelta(seconds=90) for t in logts): + silent.append((cl[:16],round((b-a).total_seconds(),1))) +print('ticks',len(sel),'silent',len(silent)) +for s in silent: print(' ',s) EOF ``` +## Ручной прогон 13:25 UTC + +Exit 0, «Pushed ✓» по всем трём фазам. Фаза 1 (и фаза 2) подтянула из bare коммит +`812173b` (`work/projects/cpm-web-extension-breakage-validation.md`, автор — Eagle). +Проверка: `/vault`, `/obsidian-syncthing` и bare — все на `812173b`, +`git status --porcelain` в `/vault` пуст. + ## Что не сделано -Корневая причина — prompt-задача: каждый тик требует LLM-раунда, а раунд иногда заканчивается без -вызова инструмента. Устранение (убрать LLM из петли) — `hermes cron edit 29851c413903 --no-agent ---script `, требует решения владельца (см. заметку 2026-09-14). +Корневая причина — prompt-задача: каждый тик требует LLM-раунда, а раунд иногда +заканчивается без вызова инструмента (0,96 % случаев). Устранение (убрать LLM из петли) — +`hermes cron edit 29851c413903 --no-agent --script `, требует решения владельца +(см. заметку 2026-09-14).