Замок вешал один, снимал другой

В Orbitly есть задачи по расписанию: напоминания, вечерний вопрос «не забыл записать траты?», недельные сводки. Раз в минуту приходит тик, задача смотрит, кому сейчас пора, и рассылает.

Однажды приложение будет крутиться в двух экземплярах — хотя бы в момент обновления без простоя. Тик придёт в оба, и оба честно разошлют напоминания. Человек получит два одинаковых сообщения.

От этого есть общепринятая защита — блокировка на стороне Postgres. Кто первым её взял, тот и работает; второй получает отказ и молча пропускает тик. Написано это было в апреле и выглядело так:

const lockResult = await db.execute(
  sql`SELECT pg_try_advisory_lock(hashtextextended(${name}, 0)) as locked`
);
// ... работа ...
await db.execute(sql`SELECT pg_advisory_unlock(hashtextextended(${name}, 0))`);

Смотрится безобидно. Беда в том, что db.execute берёт соединение из пула и сразу возвращает обратно. А pg_try_advisory_lock — замок уровня сессии: он принадлежит конкретному соединению, а не приложению. Замок вешало одно соединение, снимать приходило другое.

Как это выглядит в цифрах

Проверить оказалось просто — спросить у базы, кто есть кто:

взяли замок    → pg_backend_pid = 76783
сняли замок    → pg_backend_pid = 76784
pg_advisory_unlock вернул false
осталось висеть замков: 1

false здесь — это Postgres вежливо отвечает: «у тебя такого замка нет». Мы не проверяли ответ, поэтому он никого не смущал четыре месяца.

Почему это никого не беспокоило

Замок висел, но недолго. Соединения в пуле закрываются после двадцати секунд простоя, сессия на этом кончается, и Postgres отпускает замок сам. Следующий тик приходит через шестьдесят секунд — к нему всё уже чисто.

То есть защита работала. Просто не потому, что мы её написали, а потому что таймаут успевал раньше.

Опасным это стало в тот момент, когда я переписал рассылки на пакетную обработку. Пул стал занятее, и соединение вполне может не выстоять свои двадцать секунд простоя. Тогда замок переживает тик, pg_try_advisory_lock возвращает false — и задача пропускается. Молча. В логах ничего: отказ взять замок неотличим от честного «другой экземпляр уже работает».

Худший вид поломки. Не падение, а тишина.

Починка

Занять соединение целиком и не отпускать, пока не снимем замок:

const connection = await reserveCronConnection();
try {
  const [row] =
    await connection`SELECT pg_try_advisory_lock(hashtextextended(${name}, 0)) as locked`;
  if (row?.locked !== true) return false;
  try {
    return await fn();
  } finally {
    await connection`SELECT pg_advisory_unlock(hashtextextended(${name}, 0))`;
  }
} finally {
  connection.release();
}

В пуле для фоновых задач теперь пять соединений: четыре обработчика и одно, которое держит замок. Оно занято всё время работы задачи и ничего больше не делает — в этом и смысл.

Что я из этого вынес

Баг прожил четыре месяца не потому, что был хитрым. Он прожил четыре месяца потому, что не причинял вреда: пользователей у Orbitly пока нет, экземпляр один, а таймаут прибирал за нами. Тесты такое не ловят — с точки зрения теста всё отработало. Логи молчат — ошибки не было.

Нашёлся он побочно. Я разделял пулы соединений — сайт отдельно, фоновые задачи отдельно, чтобы рассылка не съедала соединения у живых запросов, — и по дороге пришлось спросить: а на каком, собственно, соединении живёт замок.

Занятная деталь напоследок. Предыдущая запись в этом блоге вышла 4 мая. Замок сломался 25 апреля. Всё время, пока здесь было тихо, он висел в коде.