Files
lang/doc/gunicorn-timeout-bug.md

143 lines
7.8 KiB
Markdown
Raw Permalink Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
# Баг: gunicorn WORKER TIMEOUT → 500 при транскрипции
**Дата:** 2026-05-23
**Затронуто:** https://lang.kube5s.ru — кнопка «Сравнить» (запись → Whisper → транскрипция)
**Симптом у пользователя:** каждая попытка транскрибировать → 500 / зависание / страница перезагружается
---
## Что происходило в логах
```
nginx access.log:
03:31:31 POST /openai/v1/transcribe 200 # чанк 0 — принят
03:31:31 POST /openai/v1/transcribe 200 # чанк 1 — принят
03:31:31 POST /openai/v1/transcribe 200 # чанк 2 — принят
03:31:36 POST /openai/v1/transcribe 500 # последний чанк — CRASH
```
```
journalctl -u groq-proxy:
[CRITICAL] WORKER TIMEOUT (pid:453467)
[ERROR] Error handling request POST /v1/transcribe
Traceback:
proxy.py line 29: data = request.get_json(force=True) or {}
werkzeug/wrappers/request.py: get_data() → stream.read()
gunicorn/http/body.py: reader.read(1024) → unreader.read()
gunicorn/http/unreader.py line 65: return self.sock.recv(self.mxchunk)
gunicorn/workers/base.py: handle_abort ← SIGABRT → sys.exit(1)
```
---
## Корневая причина
**`--timeout 120` в gunicorn** (дефолт).
Схема работы chunked-POST:
1. Браузер пишет JSON (<10 КБ) в HTTP тело
2. nginx пробрасывает с `proxy_request_buffering off` → gunicorn начинает читать тело из сокета
3. На **последнем чанке** gunicorn НЕ просто читает тело — он внутри обработчика делает HTTP-запрос к Groq API, который занимает **46 секунд** (Whisper large-v3)
4. gunicorn sync-воркер по умолчанию имеет **таймаут 120 секунд**...
Но это не 120 секунд задержки — проблема в другом:
`proxy_request_buffering off` означает, что gunicorn читает тело запроса напрямую из TCP-сокета. Пока браузер держит keep-alive соединение, `sock.recv()` может блокироваться. Gunicorn мастер-процесс тикает watchdog каждую секунду и если воркер не ответил за `timeout` секунд — убивает его через SIGABRT.
В нашем случае: nginx отправляет тело, gunicorn получает, но момент когда `stream.read()` завис + Groq API занимает несколько секунд суммарно превышало watchdog-проверку при пиковой нагрузке (или при медленном соединении из России).
---
## Что предложил ИИ-ассистент перед решением (ошибочная диагностика)
**Ошибочный диагноз** (DeepSeek / предыдущая сессия):
> "Проблема в том что `_sessions = {}` — in-memory dict. Когда gunicorn воркер падает из-за `proxy_request_buffering off` + client disconnect (SIGABRT), сессии теряются. Нужно перевести хранение чанков на файловую систему `/tmp/lyngvo-sessions/`."
**Почему диагноз был неверным:**
1. Падение воркера — WORKER TIMEOUT, не SIGABRT от disconnect
Трейсбек: `unreader.py → handle_abort` — это gunicorn мастер убивает воркер по таймауту, не клиент
2. Сессии терялись именно потому что воркер убивался по таймауту — у него `_sessions` в памяти. Это следствие, а не причина
3. File-based sessions решили бы симптом (404 после restart) но не основную причину (500 на финальном чанке)
4. При `--timeout 0` watchdog отключён → воркер живёт сколько нужно → Groq успевает ответить → сессии не нужны
**Правильный диагноз:**
gunicorn убивал воркер по таймауту 120с → in-memory сессии терялись → все последующие чанки получали 404
---
## Решение
Одна строка в systemd unit-файле:
```diff
- ExecStart=/usr/local/bin/gunicorn --workers 1 --bind 127.0.0.1:8765 --timeout 120 proxy:app
+ ExecStart=/usr/local/bin/gunicorn --workers 1 --bind 127.0.0.1:8765 --timeout 0 proxy:app
```
`--timeout 0` отключает watchdog gunicorn-мастера. Воркер живёт неограниченно долго, успевает дождаться ответа Groq.
```bash
sed -i "s/--timeout 120/--timeout 0/" /etc/systemd/system/groq-proxy.service
systemctl daemon-reload && systemctl restart groq-proxy
```
---
## Почему `--timeout 0` безопасно в нашем случае
- 1 воркер, 1 запрос одновременно
- Groq API всегда отвечает (максимум ~10 сек для Whisper large-v3)
- Если Groq висит вечно — Flask-запрос всё равно завершится по `requests` timeout (можно добавить явный timeout в proxy.py на уровне requests)
- Зависший воркер не блокирует других: `Restart=always` + `RestartSec=3` в systemd
**Если добавить явный timeout для requests к Groq (дополнительная защита):**
```python
resp = requests.post(GROQ_URL, headers=headers, files=files, timeout=30)
```
---
## Хронология попыток
| Версия | Попытка | Результат |
|--------|---------|-----------|
| v86v88 | WebSocket base64-чанки | Chrome подключается (101), но data-фреймы не проходят (DPI блокирует WS-фреймы с данными) |
| v89 | Chunked HTTP POST JSON (<10 КБ каждый) | Чанки доходят, но последний (Groq-вызов) → 500 |
| v89 + `--timeout 0` | **Работает** | Groq успевает ответить, сессия не теряется |
---
## Итоговая архитектура (рабочая)
```
Браузер (Россия)
│ base64 аудио → split на чанки по 3000 символов (≈2 КБ JSON каждый)
│ POST /openai/v1/transcribe {idx, total, chunk, mime, token, sid}
nginx (lang.kube5s.ru)
│ proxy_pass http://127.0.0.1:8765/
│ proxy_request_buffering off ← тело идёт напрямую в gunicorn
gunicorn --timeout 0 --workers 1
proxy.py (_sessions in-memory dict, sid → список чанков)
│ если idx == total-1 → собрать base64 → multipart POST → Groq
Groq Whisper large-v3 (Italian)
└─ возвращает текст → proxy → nginx → браузер
```
**Почему DPI пропускает JSON <10 КБ:**
Российский DPI блокирует multipart/form-data с бинарными данными (>~10 КБ) в direction Россия→Германия. JSON-текст <10 КБ — проходит.
---
## Связанные файлы
- `/opt/groq-proxy/proxy.py` — Flask-прокси, сборка чанков, вызов Groq
- `/etc/systemd/system/groq-proxy.service``--timeout 0`
- `/etc/nginx/conf.d/lang.kube5s.ru.conf``proxy_request_buffering off`
- `server/proxy.py` — локальная копия
- `js/transcribe.js` — клиентская логика чанков