Files

167 lines
15 KiB
Markdown
Raw Permalink Normal View History

# Аналитический разбор массовой проверки: 1026 адресов
> Время отчёта: 2026-10-02 08:56 UTC · Данные: снимок БД control-api на 08:46:53 UTC и лог control-api за 4 часа до остановки
> Проверено адресов: **1026** (984 завершены `done` + 42 завершены `failed`) из 6440 в очереди
> Окно прогона: 07:14:58 – 08:46:53 UTC (1 ч 32 мин). Остановлен вручную в 08:53:46 UTC.
## 1. Остановка проверок
- Проверки остановлены в 08:53:46 UTC операцией «Очистить всё» (`POST /api/v1/admin/ips/clear`).
- После остановки: очередь пуста, все 20 валидаторов `idle`, последняя выдача адреса в 08:53:43, новых выдач нет.
Реестр с историей адресов сохранён (6445 записей).
- Отвязка Floating IP с портов валидаторов при очистке: 13 зависших привязок снято прямым опросом портов
(`detached floating ip from validator port`), ещё 8 привязок, завершавшихся во время очистки, система сняла сама
(`address removed during association`). Состояние портов в самом OpenStack на момент отчёта не проверялось.
- **Первая попытка очистки не сработала.** Очистка шла дольше таймаута клиента (120 с) и оборвалась: 600 отвязок завершились
с ошибкой `context canceled`, ничего не удалилось, проверки продолжались. Повторная очистка без таймаута выполнялась 256 с.
- **Причина долгой очистки (дефект кода, не исправлен):** у завершённых адресов (`done`) в БД остаётся `fip_id`, и очистка
последовательно отвязывает все такие FIP, хотя они уже свободны (более 1000 вызовов OpenStack по ~0,2 с).
## 2. Итоги прогона
| Показатель | Значение |
|---|---|
| Адресов в очереди | 6440 |
| Завершено | 1026 (984 `done` + 42 `failed`) |
| `pass` | 227 (23% от завершённых) |
| `partial` | 757 (77%) |
| `fail` | 42 (все `failed`, вердикта по существу нет, см. раздел 4) |
| Остались в очереди / в работе на момент снимка | 5392 в очереди, 22 в работе |
Пропускная способность по 10-минутным окнам (завершено адресов за минуту): 07:10 — 5,8; 07:20 — 13,4; 07:30 — 11,6;
07:40 — 10,1; 07:50 — 10,6; 08:00 — 9,4; 08:10 — 9,7; 08:20 — 10,5; 08:30 — 10,6; 08:40 — 6,7 (окно неполное).
Цикл одного адреса (от выдачи валидатору до итога): минимум 65 с, медиана 85 с, p90 100 с, p99 115 с, максимум 125 с,
среднее 84 с (по 984 адресам `done`). Для 20 валидаторов это теоретически ~14 адресов в минуту; фактически ~10,4,
потеря около 27% из-за залипших валидаторов (раздел 4).
## 3. Фактура по накопившимся ошибкам
### 3.1. Классы ошибок (с 07:10)
В логе control-api за 4 часа на уровне `ERROR` только один вид сообщений: 41 ошибка привязки Floating IP.
| Ошибка / событие | Число | Что это |
|---|---|---|
| `lease expired` (возврат адреса по истечении лизинга) | 198 | Валидатор не подхватил задание за время лизинга. Затронуто минимум 77 адресов (часть событий без привязки к адресу) |
| Привязка FIP: `409 Cannot associate floating IP … fixed IP already has a floating IP` | 41 | На порту валидатора уже висит другой FIP. Порты: v1 — 13, v7 — 6, v13 — 6, v3 — 5, v12 — 5, v16 — 4, v17 — 2 |
| `validator_unreachable` | 7 | По одному разу: v1 и v12 (07:18:03), v13 (07:33:53), v3 (07:34:33), v7 (07:40:03), v16 (07:42:33), v17 (08:17:53) |
| `site_unreachable` | 5 | rxmsk (08:09, 08:45) и misha-v (08:09, 08:20, 08:45) |
| «Очистить всё»: `context canceled` | 600 | Последствие обрыва первой очистки (08:49), см. раздел 1 |
Чего не было: **провалов self-check — 0 из 1015** результатов; все 1015 прошли способом `control_api` (запасной `ip_echo`
не понадобился). Событий `fip_occupied` — 0, адресов `occupied` — 0.
Журнал событий за прогон: `self_check_result` 2030 (по две записи на адрес), `fip_associated` 1120, `config_received` 1015,
`aggregated` 1004, `retry_or_fail` 239 (198 лизинг + 41 привязка), `lease_expired` 198, `validator_unreachable` 7,
`site_unreachable` 5.
### 3.2. По валидаторам
| Валидатор | Завершено (`done`) | `failed` | Сбросов лизинга | `unreachable` |
|---|---|---|---|---|
| vkiplab-v1 | 2 | 17 | 49 | 1 |
| vkiplab-v12 | 2 | 13 | 51 | 1 |
| vkiplab-v13 | 13 | 10 | 41 | 1 |
| vkiplab-v16 | 38 | 2 | 19 | 1 |
| vkiplab-v7 | 36 | 0 | 21 | 1 |
| vkiplab-v17 | 50 | 0 | 10 | 1 |
| vkiplab-v3 | 50 | 0 | 7 | 1 |
| остальные 13 (v2, v4–v6, v8–v11, v14, v15, v18–v20) | 60–63 | 0 | 0 | 0 |
(Сбросы лизинга и `unreachable` в таблице — только за прогон, с 07:10. У v14, v18 и v2 в истории БД есть сбросы лизинга
за 1 октября, к этому прогону они не относятся.)
- **v1 и v12** не подхватили ни одного задания после 07:17 (последний подхват 07:17:29 и 07:17:26).
- **v13** — после 07:33:16.
- **v7, v16, v17, v3** залипали временно и затем восстановились; механизм восстановления не выяснен.
### 3.3. 42 адреса `fail`
- По валидаторам: v1 — 17, v12 — 13, v13 — 10, v16 — 2. Все 42 исчерпали повторы: `retry_count` = 4 и `attempt_number` = 4 у каждого.
- Причины неудачных попыток по этим адресам: 143 сброса лизинга и 25 ошибок привязки `409`.
- **Ни одной проверки по ним не выполнено** (в таблице проверок у этих адресов 0 записей): адреса не получили вердикта,
и `fail` здесь не характеризует сами адреса.
- Появлялись равномерно с 07:31 до 08:46 (4–10 за 10 минут).
- Подсети: 37.139.x, 79.137.x, 83.166.x и другие, без концентрации.
## 4. Причины
Подтверждены по БД и логам control-api. Логи агентов на самих валидаторах не изучались.
**Причина 1. Валидатор получает два адреса сразу и застревает.** Два дефекта вместе:
- Heartbeat (`queries_validators.go`) возвращает валидатор из `unreachable` в `idle`, не проверяя, что за ним числится адрес.
Адрес с долгими внешними проверками (3–4 таймаута по 10 с) блокирует агента больше 30 с (порог
`heartbeat_timeout_seconds`), control-api помечает валидатор недоступным, затем возвращает в `idle` занятым.
- При завершении старого адреса `ReleaseFIP` (`queries_ipqueue.go`) освобождает валидатор по его имени, а не по адресу.
- Подтверждение: **35 двойных выдач** (два адреса одному валидатору с интервалом ~5 с) в логе: v1 — 10, v12 — 9, v7 — 6,
v13 — 4, v17 — 3, v16 — 2, v3 — 1. Из 1265 выдач в логе.
**Причина 2. Регрессия моей правки с параллельной привязкой.** Защита от дублей в `orchestrator.go:149` ключуется по
валидатору (`assign:<validator>`). Вторая выдача того же валидатора пропускает привязку, и адрес стоит в `assigning_fip`
до истечения лизинга. В БД у валидатора одно поле `current_ip_id`, оно указывает на последний выданный адрес, агент по нему
получает пустое задание, лизинг истекает, валидатор берёт новый адрес, и круг повторяется. Ошибки `409` — следствие: на
порту остаётся FIP первого адреса, привязать второй нельзя.
**Причина 3. Агент молчит во время долгих проверок.** Heartbeat отправляется только между заданиями; адреса с несколькими
таймаутами ведут к `unreachable` (пусковой механизм причины 1). Пример: v1 проверял `37.139.32.1`, v12 — `37.139.32.4`;
у обоих проваливались все четыре внешних HTTPS-цели (~40 с таймаутов), в 07:18:03 оба помечены `unreachable`.
**Дефект очистки.** См. раздел 1: отвязка всех `done`-адресов последовательно.
## 5. Результаты проверок самих адресов
**Почему 77% `partial`:** 735 адресов проваливают только исходящие HTTPS, ещё 22 — исходящие и входящие.
| Цель (egress HTTPS) | Адресов с провалом (из 984) |
|---|---|
| `packages.ubuntu.com` | 698 (71%) |
| `repo.almalinux.org/almalinux/` | 304 (31%) |
| `github.com` | 251 (26%) |
| `hub.docker.com` | 17 (2%) |
Число провалов на один `partial`-адрес: 1 — 392 адреса, 2 — 202, 3 — 136, 4 и больше — 27.
По подсетям (доля адресов с провалом цели):
| Подсеть | Адресов | `packages.ubuntu.com` | `repo.almalinux.org` | `github.com` | `hub.docker.com` | Доля `partial` |
|---|---|---|---|---|---|---|
| 83.166.x | 435 | 80% | 53% | 42% | 0% | 92% |
| 37.139.x | 418 | 62% | 11% | 10% | 4% | 63% |
| 79.137.x | 109 | 66% | 19% | 18% | 0% | 68% |
| 5.188.x | 22 | 59% | 0% | 0% | 0% | 59% |
- `packages.ubuntu.com` проваливается у всех подсетей и во все окна. Доля проваленных строк egress для этой цели по 10-минутным
окнам выросла с 26% до 40% (строки включают HTTPS и ICMP, поэтому реальная доля HTTPS вдвое выше).
- Доля `partial` почти одинакова у всех валидаторов (72–84%; v1 — 100% по 2 адресам, v12 — 50% по 2): причина в самом адресе
или во внешнем ресурсе, а не в валидаторе.
- Провалы `repo.almalinux.org` и `github.com` сильно зависят от подсети (83.166.x — 53% и 42%, 37.139.x — 11% и 10%).
- Успешные HTTPS-проверки: медиана 200 мс, p90 6707 мс (много ответов близко к таймауту 10 с).
**Входящие проверки.** Провалы только у `inbound-site-1` (33 пробы из 2934) и `inbound-site-3` (50 из 2931); `inbound-site-2` — 0 из 2952,
`inbound-site-4` — 1 из 2952. Провалы всплесками в 08:00, 08:20 и 08:40 по ICMP, SSH и TCP 22; у 20 адресов упали все пробы
одной площадки. Пробер rxmsk и misha-v в эти же минуты отмечены `unreachable`. Причина недоступности проберов не выяснена.
## 6. Рекомендации
1. **Исправить оркестратор** (до повторного запуска): защита от дублей по адресу, `unreachable` → `assigned` вместо `idle`,
освобождение валидатора только по текущему адресу, heartbeat агента в отдельном потоке.
2. **Исправить очистку:** отвязывать только действительно привязанные FIP (без `fip_released_at`) и параллельно.
3. **Перепроверить 42 адреса** после исправления: вердикта по существу они не получили. Все `fail` с причиной «lease expired» считать недействительными.
4. **Решить по `packages.ubuntu.com`:** 71% `partial` и 10 с таймаута на каждый такой адрес; если ресурс нестабилен, убрать или заменить.
5. **Проверить причины `site_unreachable`** у проберов (возможна перегрузка при большой очереди).
6. Проверить в OpenStack, что порты валидаторов свободны от Floating IP.
## 7. Что не проверено
- Состояние портов и Floating IP в самом OpenStack.
- Логи агентов `validator-agent` на валидаторах и логи проберов (причины блокировок heartbeat подтверждены по времени и
событиям control-api, не по логам агентов).
- Почему залипшие v7, v16, v17, v3 восстановились.
- Причины провалов внешних HTTPS-целей (ресурс, сеть облака или фильтрация) и недоступности проберов.
## 8. Источники данных
- Снимок БД control-api: `.backup` на 08:46:53 UTC (таблицы `ip_queue`, `checks`, `events`, `validators`, `sites`).
- Лог контейнера control-api за 4 часа до остановки (1504 строки) и за период очистки.
- Статус и результат очистки: HTTP 200 за 256,7 с.