В начале ночного сеанса в логах появилось сообщение от пользователя: "ошибка конвертации на бою". Проверяю контейнер epich_watch:

docker --context epich logs epich_watch --tail 60 2>&1

В выводе сразу двое подозреваемых. Первый очевиден:

ffmpeg error: signal: killed
torrent: file not found after download room f7f8-...: ...ep5.mkv

ffmpeg убит по OOM или таймауту, это случается. Интереснее вторая строка: файл ep5.mkv не найден после завершения загрузки. Но пользователь уточнил, что ep4 ffmpeg убили раньше, а ep5 он загружал уже новой попыткой, и именно ep5 не нашёлся. Это уже не OOM, а что-то другое.

Как устроен watch.epich.ru

Сервис позволяет двум людям смотреть видео синхронно. Один загружает файл (или magnet-ссылку), сервер конвертирует его в HLS, и оба смотрят через hls.js. Пауза одного тут же останавливает видео у второго через WebSocket.

sequenceDiagram participant U as Пользователь participant S as Go-сервер (port 8098) participant T as anacrolix/torrent participant F as ffmpeg participant B as Браузер (hls.js) U->>S: POST /api/torrent (magnet-ссылка) S->>T: AddTorrentSpec + GotInfo() T-->>S: список файлов S-->>U: WS: torrent_files [{name, size}] U->>S: POST /api/torrent-download {fileIndex: 4} S->>T: f.Download() loop каждые 2 сек T-->>S: BytesCompleted / Length S-->>U: WS: download_progress {percent} end T-->>S: completed >= length Note over T,S: .part файл ещё не переименован! T->>T: верификация кусочков T-->>S: rename ep5.mkv.part → ep5.mkv S->>F: ffmpeg -i ep5.mkv ... -hls_flags append_list loop каждые 2 сек F-->>S: прогресс конвертации S-->>U: WS: transcode_progress {percent} end F-->>S: HLS готов (playlist.m3u8) S-->>U: WS: video_status {status: "ready", active_video_id} U->>B: hls.js.loadSource(playlist.m3u8)
Цепочка от magnet до воспроизведения. Два бага прячутся именно в переходах между стадиями.

Стек: Go 1.24, gorilla/websocket, anacrolix/torrent v1.61.0, ffmpeg с флагами -hls_flags append_list+temp_file, hls.js 1.5.15 на фронтенде. Состояние комнаты: только в памяти процесса, никаких баз данных для runtime-данных.

Баг 1: файл ещё не файл

anacrolix/torrent пишет данные в ep5.mkv.part и переименовывает в ep5.mkv только после верификации всех кусочков. Верификация начинается, когда BytesCompleted() >= Length(). Но это не одновременные события.

Гонка состояний: after bytes_completed >= length выполнение выходит из download-loop и сразу делает os.Stat(srcPath). В этот момент ep5.mkv ещё не существует: анакроликс продолжает верификацию. Stat возвращает "no such file or directory", и транскодинг не запускается.

Это хорошо видно при du -sh файлов в пресловутой проблемной комнате: ep4 занимал 4.3 ГБ, ep5: 3.8 ГБ, но из-за sparse-предварительного выделения на диске они занимали лишь 1.3 ГБ суммарно (файлы .part (sparse), данные записываются не подряд).

Как поправили

Retry-цикл между download-loop и os.Stat: ждём появления конечного файла до 10 секунд с шагом 100 мс. Это изначально было inline-циклом, а в следующем коммите вынесено в хелпер waitForFile:

func waitForFile(path string, maxAttempts int, interval time.Duration) bool {
    for i := 0; i < maxAttempts; i++ {
        if _, err := os.Stat(path); err == nil {
            return true
        }
        time.Sleep(interval)
    }
    return false
}

// В startTorrentDownload после download-loop:
if !waitForFile(srcPath, 100, 100*time.Millisecond) {
    log.Printf("torrent: file did not appear after 10s room %s: path=%s", room.ID, srcPath)
}
// os.Stat(srcPath) ниже уже после retry

Почему 10 секунд? Верификация кусочков занимает от доли секунды до нескольких, в зависимости от диска и размера файла. Для ep5 объёмом 3.8 ГБ это единицы секунд на SSD. Десять секунд: запас с большим перекрытием.

Баг 2: клиент не знает, какое видео активно

После исправления первого бага выяснилось кое-что ещё: торрент загружался и конвертировался нормально, но браузер по-прежнему загружал ep4. Пользователь описал это так: "я загружаю пятую серию, а после конвертации вижу четвёртую".

Это отдельный баг, и он оказался интереснее первого.

Анатомия промаха

На сервере setActiveVideoID(ep5ID) вызывается внутри горутины после завершения скачивания. Переменная activeVideoID обновляется правильно. Потом запускается transport: startTranscodeFrom делает broadcastAll с типом video_status:transcoding. Но этот broadcast не содержал active_video_id.

sequenceDiagram participant SRV as Сервер participant C1 as Клиент 1 (загружает) participant C2 as Клиент 2 (партнёр) Note over C1,C2: currentActiveVideoID = "ep4abc" SRV->>SRV: setActiveVideoID("ep5xyz") SRV-->>C1: {t:"video_status", status:"transcoding"} SRV-->>C2: {t:"video_status", status:"transcoding"} Note over C1,C2: currentActiveVideoID по-прежнему "ep4abc"! SRV-->>C1: {t:"video_status", status:"ready"} C1->>C1: onVideoStatus("ready") C1->>C1: loadServerVideo(currentActiveVideoID) Note over C1: загружает HLS ep4, не ep5!
Сервер обновил activeVideoID, но не сообщил клиентам. Когда пришёл статус "ready", фронтенд построил URL из устаревшего ID.

На фронтенде переменная currentActiveVideoID обновлялась только при получении сообщения video_activated, отдельного события, которое отправляется при явном переключении видео из UI. При torrent-загрузке это событие не отправлялось.

Получался разрыв: сервер знает актуальный ID, браузер: нет. Когда hls_started или ready приходило к клиенту, loadServerVideo() строила URL из устаревшего ep4ID. ep4 мог быть уже полностью готов (он конвертировался раньше и был убит по OOM), поэтому видео грузилось без ошибки, только не то.

Исправление

Решение в двух строках кода. На сервере: добавить active_video_id в broadcast при смене статуса:

// transcode.go — startTranscodeFrom
room.broadcastAll(mustMarshal(map[string]any{
    "t":               "video_status",
    "status":          string(VideoTranscoding),
    "active_video_id": videoID, // <-- добавлено
}))

// main.go — handleUpload  
room.broadcastAll(mustMarshal(map[string]any{
    "t":               "video_status",
    "status":          string(VideoUploading),
    "active_video_id": videoID, // <-- добавлено
}))

На фронтенде: читать active_video_id до вызова onVideoStatus, потому что именно onVideoStatus вызывает loadServerVideo():

case "video_status":
  // active_video_id может прийти вместе со статусом —
  // обновляем до onVideoStatus, чтобы loadServerVideo использовал верный ID
  if (msg.active_video_id) currentActiveVideoID = msg.active_video_id;
  onVideoStatus(msg.status);
  break;
Принцип из этого бага: если сервер обновляет state и сразу делает broadcast, клиент должен получить весь необходимый контекст в том же сообщении. Иначе любой код, который реагирует на broadcast и читает client-side state, будет использовать устаревшее значение. Отдельное "синхронизирующее" сообщение позже: это гонка.

Тесты и рефакторинг ради тестируемости

После каждого фикса добавлялись unit-тесты. Для waitForFile написались три сценария: файл уже есть, файл появляется через 50 мс, файл так и не появился. Тест с появлением файла создаёт временный файл в горутине через time.AfterFunc:

func TestWaitForFile_FileAppearsLater(t *testing.T) {
    dir := t.TempDir()
    path := filepath.Join(dir, "target.mkv")
    time.AfterFunc(50*time.Millisecond, func() {
        os.WriteFile(path, []byte("x"), 0o600)
    })
    if !waitForFile(path, 20, 20*time.Millisecond) {
        t.Error("expected file to appear within 400ms")
    }
}

С тестом на active_video_id в broadcast получилась история. Первая попытка: создать комнату, запустить startTranscodeFrom, проверить что broadcast содержит нужное поле. Тест падал, потому что os.MkdirAll("/app/data/hls/...") возвращал ошибку, в тестовом окружении нет /app. Но перед MkdirAll broadcast ещё не был отправлен, проверять было нечего.

Правильное решение: поменять порядок: сначала broadcast, потом MkdirAll. Это и лучше для UX (партнёр видит "конвертирую" раньше), и тест начинает работать без моков файловой системы. При ошибке MkdirAll теперь явно переводим комнату в VideoError и сообщаем об этом обоим клиентам:

func startTranscodeFrom(room *Room, inputPath string, ...) {
    go func() {
        // Сначала атомарно меняем статус и сообщаем клиентам
        if !room.trySetVideoStatus(fromStatus, VideoTranscoding) {
            return
        }
        room.broadcastAll(mustMarshal(map[string]any{
            "t":               "video_status",
            "status":          string(VideoTranscoding),
            "active_video_id": videoID,
        }))

        // Потом файловые операции
        hlsDir := hlsDirPath(room.ID, videoID)
        if err := os.MkdirAll(hlsDir, 0o700); err != nil {
            if room.trySetVideoStatus(VideoTranscoding, VideoError) {
                room.broadcastAll(mustMarshal(map[string]any{...}))
            }
            return
        }
        // ... ffmpeg ...
    }()
}

Теперь тест создаёт комнату с двумя mock-клиентами, запускает функцию и читает из канала:

func TestStartTranscodeFrom_BroadcastsActiveVideoID(t *testing.T) {
    h := &Hub{rooms: make(map[string]*Room)}
    r := h.GetOrCreate("test-broadcast")
    r.setActiveVideoID("ep4videoid0000")

    c1 := &Client{room: r, send: make(chan []byte, 16)}
    c2 := &Client{room: r, send: make(chan []byte, 16)}
    r.join(c1)
    r.join(c2)

    startTranscodeFrom(r, "/nonexistent/input.mkv", VideoDownloading,
        "ep5videoid0000", "ep5.mkv", 1000)

    select {
    case raw := <-c1.send:
        var msg map[string]any
        json.Unmarshal(raw, &msg)
        if msg["active_video_id"] != "ep5videoid0000" {
            t.Errorf("active_video_id = %v, want ep5videoid0000", msg["active_video_id"])
        }
    case <-time.After(200 * time.Millisecond):
        t.Fatal("no broadcast received")
    }
}

1.3 ГБ на сервере

Пока разбирался с багами, заглянул в хранилище торрентов на проде:

docker --context epich exec epich_watch du -sh /app/data/watch-torrents/*

Нашлась директория комнаты от 14 марта (572f-484f-7081-d7c9) : именно та, где произошёл первоначальный сбой. В ней два sparse-файла: ep4.mkv.part (4.3 ГБ виртуально, ~0.8 ГБ реально) и ep5.mkv.part (3.8 ГБ виртуально, ~0.5 ГБ реально). Сервер перезапускался после того сбоя, komнатa была брошена, но файлы остались.

Итог: удаление директории освободило 1.3 ГБ диска. : файлы реально живут на хосте даже после рестарта контейнера.

Постоянная уборка "потерянных" хранилищ при старте сервиса: задача для бэклога. Комната без участников с несуществующим torrent-handle может уводить данные в "сирот".

Хронология коммитов

gitGraph commit id: "fea10e0: fix waitForFile retry" commit id: "667e819: test waitForFile (3 тест)" commit id: "aaac9fb: fix active_video_id в broadcast" commit id: "156a0d1: test BroadcastsActiveVideoID + broadcast до MkdirAll"
Четыре коммита: сначала минимальный фикс в продакшн, потом тест, снова фикс, снова тест.

Что унёс из этого сеанса

anacrolix/torrent и переименование файлов

Библиотека использует .part-суффикс и делает rename только после верификации SHA1 всех кусочков. Это задокументировано в исходниках, но легко пропустить. BytesCompleted() >= Length() не означает "файл на диске": это означает "все байты получены и записаны в storage". Верификация занимает ещё некоторое время.

Хелпер waitForFile с разумным таймаутом: дешёвое и работающее решение. Альтернатива: подписаться на channel t.Complete(), но он есть только для целых torrent-объектов, не для отдельных файлов.

WS broadcast: контракт состояния

Когда сервер меняет state и отправляет broadcast об этом изменении, клиент должен получить весь необходимый для реакции контекст внутри одного сообщения. Разделение "меняем state" и "сообщаем ID" на два разных места создаёт окно гонки.

Простое правило: если broadcast описывает событие "X сменило своё активное видео на Y", то и X, и Y должны быть в теле сообщения. Клиент не обязан помнить, что было "активным" до.

Порядок операций определяет тестируемость

Код "broadcast → MkdirAll" проще тестируется, чем "MkdirAll → broadcast". Не потому что так удобнее писать тест, а потому что первый вариант имеет более чёткий инвариант: клиент всегда получает уведомление о смене статуса, даже если файловая операция потом упадёт. Это и правильнее семантически.

2 независимых бага в одной цепочке
4 unit-теста добавлено
10 с максимальное ожидание rename
1.3 ГБ освобождено на диске