diff --git a/family/documents/vault-sync/2026-09-14-cron-api-timeout-sync-outage.md b/family/documents/vault-sync/2026-09-14-cron-api-timeout-sync-outage.md index 63bab20c..8f1e4d2c 100644 --- a/family/documents/vault-sync/2026-09-14-cron-api-timeout-sync-outage.md +++ b/family/documents/vault-sync/2026-09-14-cron-api-timeout-sync-outage.md @@ -2,7 +2,7 @@ tags: [vault-sync, incident, cron, deepseek, api-timeout, taiga] created: 2026-09-14 updated: 2026-09-14 -status: resolved 2026-09-14 21:40 UTC — sync прогнан вручную, все три фазы Pushed ✓, данные целы; причина (LLM timeout в cron-задаче) не устранена на уровне конфига +status: resolved 2026-09-14 21:40 UTC — sync прогнан вручную, все три фазы Pushed ✓, данные целы; причина (LLM timeout в cron-задаче) не устранена на уровне конфига. 23:45 UTC — найден второй режим отказа: ~6,6 % тиков `completed` без запуска скрипта (см. раздел ниже) --- # Incident 2026-09-14: 3-часовой разрыв в vault-sync — cron-задача блокировалась API-таймаутами deepseek @@ -18,7 +18,7 @@ status: resolved 2026-09-14 21:40 UTC — sync прогнан вручную, в [2026-09-14 21:30:52] [syncthing] Pushed ✓ ``` -GAP 18:30:16 → 21:30:52 = **180.6 мин**. Остальные разрывы за сутки — штатные 9–10 мин (пропущенные тики диспетчера). +GAP 18:30:16 → 21:30:52 = **180.6 мин**. Остальные разрывы за сутки — 9–10 мин. **Важно:** это не «пропуск тика диспетчером» — см. второй режим отказа ниже, тик запускается и даже помечается `completed`, но скрипт в нём не исполняется. ## Корень: не диспетчер, а LLM-вызовы внутри задачи @@ -67,6 +67,40 @@ for r in c.execute(\"select claimed_at,finished_at,status,error from executions После ручного прогона 21:40 каденция вернулась сама, без вмешательства в конфиг: тики 21:35→22:30 — **12 запусков/час, failed = 0**, разрывов >10 мин нет. Все три репозитория по-прежнему на одном коммите (`ec21efe`), рабочие деревья чистые. Итог: инцидент закрыт по данным, причина (LLM timeout в prompt-задаче) остаётся открытой — см. «Что можно сделать». +## Второй режим отказа: тик `completed` за ~9 с, но скрипт не запущен (найдено 2026-09-14 23:45 UTC) + +**Симптом:** в `/tmp/vault-sync.log` разрыв 10 мин (например, `23:35:07 → 23:45:10`), при этом в `executions.db` тик `2026-09-14T23:40:01` имеет статус **`completed`**, `finished_at = 23:40:10` (9 с), `error = ''`. В логе за `2026-09-14 23:40` — **ноль строк**, хотя `sync-vault.sh` всегда печатает три timestamped `Pushed ✓`. + +**Механика:** prompt-задача исполняется LLM-раундом; если агент отвечает текстом и **не делает вызова инструмента** (короткий ответ, «нечего делать»), запуск считается успешным, но bash-команда не выполняется. Скрипт не вызывался вообще — это не graceful skip `fetch`, не конфликт и не пропуск диспетчера. + +**Масштаб (замер за 24 ч, 2026-09-14):** из 258 запусков job_id `29851c413903` — **17 запусков (6,6 %) завершились без единой строки в логе**, из них 12 «здоровых» (~7–12 с, статус `completed`) и 5 в окне таймаутов 18:35–21:20. То есть ~1 из 15 тиков молча ничего не синхронизирует, а лог sync при этом выглядит безобидно (просто 10-минутный разрыв). + +**Аудит — сверка executions.db с логом (выполнять при любом подозрении на «пропущенный тик»):** + +```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=list(c.execute("select claimed_at,finished_at,status from executions where job_id='29851c413903' order by claimed_at")) +p=lambda s: datetime.fromisoformat(s) +cut=p(rows[-1][0])-timedelta(hours=24) +ex=[(p(a),b) for a,b,st in rows if p(a)>=cut] +txt=open('/tmp/vault-sync.log',errors='replace').read() +tz=ex[0][0].tzinfo +ticks=[datetime.strptime(t,'%Y-%m-%d %H:%M:%S').replace(tzinfo=tz) for t in + set(re.findall(r'\[(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d)\] \[syncthing\]', txt))] +ticks=[t for t in ticks if t>=cut] +miss=[(a.isoformat(),b) for a,b in ex if not any(0<=(t-a).total_seconds()<=300 for t in ticks)] +print(f'executions 24ч: {len(ex)} | тиков в логе: {len(ticks)} | без записи в лог: {len(miss)}') +for m in miss: print(' ', m) +EOF +``` + +**Данные не теряются** (git-синк идемпотентен, следующий удачный тик догоняет всё), но фактическая каденция гарантированно ниже номинальных 5 мин — замер 2026-09-14: 245 реальных синков вместо ~288. + +**Вывод:** это аргумент за `--no-agent --script` (пункт 1 ниже) — LLM в петле не только блокирует очередь таймаутами, но и в ~6 % случаев просто не вызывает команду. + ## Связанные заметки - [[2026-09-02-dubious-ownership-and-merge-cleanup]] — предыдущий инцидент sync (dubious ownership /vault.git) - [[2026-08-31-syncthing-truenas-incident]]