[2026-09-16 13:28:15] taiga-vault: family/documents/vault-sync/2026-09-16-silent-tick-clusters.md

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 <path>`, требует решения владельца (см. заметку 2026-09-14).
+Корневая причина — prompt-задача: каждый тик требует LLM-раунда, а раунд иногда
+заканчивается без вызова инструмента (0,96 % случаев). Устранение (убрать LLM из петли) —
+`hermes cron edit 29851c413903 --no-agent --script <path>`, требует решения владельца
+(см. заметку 2026-09-14).