109 lines
6.2 KiB
Markdown
109 lines
6.2 KiB
Markdown
---
|
||
tags: [vault, git, sync, cron, incident, correction]
|
||
date: 2026-09-16
|
||
---
|
||
|
||
# 2026-09-16 — перепроверка молчащих тиков: «кластеры» оказались артефактом метода
|
||
|
||
Утренняя находка этого дня («молчащие тики идут кластерами 4–5 подряд»,
|
||
16:55→17:15 и 23:45→00:00) **опровергнута** при перепроверке 13:25 UTC.
|
||
|
||
## Что было не так
|
||
|
||
Первый скрипт сверки сравнивал **минуту** тика из `executions.db` (`claimed_at[:16]`)
|
||
с минутой timestamped-строки `[syncthing] Pushed ✓` в логе.
|
||
|
||
Скрипт стартует внутри тика не мгновенно: при `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 с; иногда он переходит
|
||
через границу минуты — именно это и порождало ложные «пропуски».
|
||
|
||
## Корректный метод
|
||
|
||
Сопоставлять по **окну**, а не по минуте: строка `[syncthing]` должна попадать
|
||
в `[claimed_at − 45 с; finished_at + 90 с]`. Метод замера 2026-09-14
|
||
(окно 300 с) был корректен — цифра 6,6 % за те сутки под сомнение не ставится.
|
||
|
||
## Фактические цифры (окно текущего лога)
|
||
|
||
Окно 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, 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()
|
||
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` пуст.
|
||
|
||
## Поправка 22:30 UTC — кластер реален, но метод замера уже верный
|
||
|
||
Перезамер тем же **оконным** методом (окно лога 2026-09-15 11:35:19 → 2026-09-16 22:30:20):
|
||
**421 тик, 7 молчащих (1,66 %)** — вдвое больше, чем на 13:25 (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 с | |
|
||
| 2026-09-16 13:45 | 6,5 с | |
|
||
| 2026-09-16 16:45 | 6,0 с | |
|
||
| 2026-09-16 18:25 | 7,1 с | |
|
||
| 2026-09-16 20:15 | 7,3 с | |
|
||
|
||
5 из 7 — в интервале 09-16 12:10 → 20:15 (~1 молчащий на 2 ч вместо ожидаемого 1 на ~14 ч).
|
||
То есть артефактом метода были конкретные «кластеры» 16:55→17:15 и 23:45→00:00 (их
|
||
опровержение в начале заметки остаётся в силе), но **сам феномен кластеризации реального
|
||
времени существует**. Минутное сопоставление по-прежнему непригодно, оконное — пригодно.
|
||
|
||
Дополнительно в `executions.db` найден отдельный режим отказа, не связанный с LLM:
|
||
`2026-09-15 11:30:10 status=failed error='Fire claim lost; execution was not started.'`
|
||
— тик потерян на стороне планировщика, скрипт не вызывался. Единичный случай, на 22:30
|
||
не повторялся.
|
||
|
||
## Что не сделано
|
||
|
||
Корневая причина — prompt-задача: каждый тик требует LLM-раунда, а раунд иногда
|
||
заканчивается без вызова инструмента (0,96 % случаев). Устранение (убрать LLM из петли) —
|
||
`hermes cron edit 29851c413903 --no-agent --script <path>`, требует решения владельца
|
||
(см. заметку 2026-09-14).
|