golang

Ваш recover() эту ошибку не поймает

  • воскресенье, 1 ноября 2026 г. в 00:00:07
https://habr.com/ru/companies/otus/articles/1099260/

Привет, Хабр!

Почти в каждом Go‑сервисе в Kubernetes первым в цепочке стоит middleware, который ловит панику через defer и recover(), пишет её в лог и отвечает 500. Его ставят в первый же день и больше не трогают, потому что с ним сервис переживёт любую панику в обработчике, потеряв один запрос.

Где‑то рядом лежит глобальная map под кэш или счётчики, и пишут в неё из обработчиков без мьютекса, потому что «там же просто инкремент».

Однажды на пике нагрузки под уходит в рестарт, потом ещё в один и в итоге в CrashLoopBackOff, а в логе остаётся одна строка fatal error: concurrent map writes и стек.

Строки recovered там нет ни одной, хотя recover() написан и в middleware, и в самом обработчике.

Причём падает такая map не всегда. Часть гонок проходит без всякого fatal, и тогда в логе вообще ничего нет, а неверные цифры уже лежат в данных.

recover() здесь ни при чём

Чтобы это воспроизвести, хватает сервиса из одного обработчика. В нём middleware с recover(), обработчик со своим recover() и глобальная map.

var hits = map[string]int{} // счётчики без синхронизации

func recoverMW(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		defer func() {
			if v := recover(); v != nil {
				log.Printf("middleware: recovered: %v", v)
				http.Error(w, "internal error", http.StatusInternalServerError)
			}
		}()
		next.ServeHTTP(w, r)
	})
}

func hit(w http.ResponseWriter, r *http.Request) {
	defer func() {
		if v := recover(); v != nil {
			log.Printf("handler: recovered: %v", v)
		}
	}()
	key := r.URL.Query().Get("k")
	hits[key]++                       // строка 33
	fmt.Fprintf(w, "%d\n", hits[key])
}

Запись в nil‑map даёт обычную панику, и от неё middleware защищает исправно, ловит и отвечает 500.

Паника в обработчике без своего recover() тоже не роняет сервер, потому что net/http сам ловит панику, закрывает соединение и пишет стек в лог.

На /hit я пустил 50 параллельных клиентов со 100 разными ключами. Здесь и дальше сервис работал на Go 1.24.7, 1.26.10 и 1.27.3, с разной нагрузкой, на одном и на двух ядрах, с -race и без.

go1.24.7   died_after=0.026s  ok_before_death=213  server_exit=2
go1.26.10  died_after=0.021s  ok_before_death=284  server_exit=2
go1.27.3   died_after=0.009s  ok_before_death=23   server_exit=2

fatal error: concurrent map writes

goroutine 80 [running]:
internal/runtime/maps.fatal({0x7127a9?, 0x41197b?})
	.../src/runtime/panic.go:1181 +0x18
main.hit({0x72ffd8, 0x2789db4383c0}, 0x0?)
	/srv/main.go:33 +0x7f
...
main.main.recoverMW.func1(...)
	/srv/main.go:22 +0x63

Процесс умер с кодом 2 за доли секунды на всех трёх версиях, хотя в стеке видны оба кадра с defer и recover() — и обработчик, и middleware.

Заметив одновременную запись в map, рантайм вызывает вместо panic внутреннюю функцию fatal. Она печатает сообщение и стек и сразу завершает процесс через exit(2), поэтому стек никто не раскручивает, отложенные функции не выполняются и recover() просто не получает управления.

Тот же fatal срабатывает при разблокировке незаблокированного sync.Mutex или RWMutex, при all goroutines are asleep — deadlock! и ещё в нескольких местах.

Почему map вообще оставили без защиты? Авторы Go объясняют это в FAQ тем, что чаще всего map живёт в одной горутине, а если её трогают из нескольких, она обычно лежит внутри структуры побольше, которую и так закрывает блокировка.

Брать мьютекс на каждую операцию значило бы замедлить почти все программы ради немногих. Взамен рантайм с Go 1.6 умеет дёшево и «по возможности» замечать неправильный параллельный доступ к map и останавливать программу.

Сколько живёт сервис с такой map

Эта проверка «по возможности» держится на флаге в заголовке map. Перед записью рантайм смотрит, не стоит ли флаг, ставит его, а после записи снимает. Переключают его через XOR, чтобы при двух одновременных писателях гонку с большей вероятностью заметили оба, но атомарной проверка от этого не становится. Падение случается, только если две операции с одной map действительно пересеклись во времени.

На 50 клиентах без ограничения скорости это происходит за доли секунды. При живом трафике запросы приходят вразнобой, и сервис держится заметно дольше.

пуассоновский поток, GOMAXPROCS=2, по одному прогону на точку
100 rps    падение через 19–23 с,  после 1891–2282 запросов
 30 rps    падение через 26–64 с,  после 793–1942 запросов
 10 rps    падение через 142 с,    после 1438 запросов

равномерный поток (строго через одинаковые интервалы)
100 rps    прожил 10 минут без падения
 10 rps    прожил 10 минут без падения

При равномерном потоке два запроса почти никогда не попадают в обработку одновременно, тогда как у случайного потока такие совпадения регулярны. Число запросов до падения почти не зависело от нагрузки и держалось в пределах от 800 до 2300 при 10–100 rps.

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

Сервис с GOMAXPROCS=1 за минуту и от полумиллиона до 1,3 млн запросов не упал ни разу. На синтетике одно ядро не помогает: четыре горутины в цикле вставляют новые ключи, map растёт, и программа падает за 0,02–0,34 секунды. По стеку видно, что вторую горутину сняли с процессора посреди вставки, во время роста таблицы.

Данные портятся и без всякого fatal

До этих прогонов я считал падение худшим, что может сделать такая map, но выяснилось, что гонка бывает и тогда, когда детектор в map молчит.

hits[key]++ состоит из двух операций с map — чтения и записи, — а детектор ловит только пересечение двух операций во времени.

Допустим, одна горутина прочитала значение, и её сняли с процессора. Вторая за это время сделала свою работу, а потом первая вернулась и записала устаревшее значение. Тогда ни одна операция ни с кем не пересеклась.

Две горутины по 100 000 раз делают:

v := hits["x"]
hits["x"] = v + 1

Я запустил это на одном ядре с принудительным переключением горутины между чтением и записью, и все три версии дали одно и то же.

go1.24.7   GOMAXPROCS=1  expected=200000  got=100000  lost=100000  exit=0
go1.26.10  GOMAXPROCS=1  expected=200000  got=100000  lost=100000  exit=0
go1.27.3   GOMAXPROCS=1  expected=200000  got=100000  lost=100000  exit=0

Половина инкрементов потеряна, а процесс вышел с кодом 0, как будто всё прошло нормально. На двух ядрах и без принудительного переключения около половины прогонов кончались fatal. В части остальных, от долей процента до нескольких процентов в зависимости от загрузки машины, итог был 1000 вместо 2000, и никакого fatal не было.

Сама map цела, ключ в ней один и без дубликатов, просто одна устаревшая запись затёрла тысячу чужих инкрементов.

Для счётчика просмотров это неточная цифра в отчёте, для остатка на складе или баланса — уже деньги.

Падает такой сервис, только когда ему повезёт попасть в пересечение, а до этого теряет данные молча, без единой строки в логе.

Трейс, в котором осталась одна горутина

Если сервис всё‑таки упал и в логе есть трейс, что в нём искать, зависит от версии Go. Для сравнения я написал программу, где 1000 горутин ждут на канале, а две пишут в общую map, и уронил её на трёх версиях.

go1.24.7   GOTRACEBACK по умолчанию   197 093 байта   8029 строк   1003 горутины
go1.26.10  GOTRACEBACK по умолчанию       324 байта      9 строк      1 горутина
go1.27.3   GOTRACEBACK по умолчанию       331 байт       9 строк      1 горутина
go1.26.10  GOTRACEBACK=all            197 207 байт    8029 строк   1003 горутины

До Go 1.25 включительно fatal из‑за map печатал стеки всех горутин, даже с GOTRACEBACK по умолчанию. На сервисе с десятками тысяч горутин это мегабайты лога, и в обсуждении этой проблемы упоминали гонку на map в продакшене, которая выдала около 3 ГБ стектрейсов.

В Go 1.26 в runtime/runtime1.go поменяли одну строку — >= на >, — и теперь печатается только горутина, которая заметила гонку. В release notes Go 1.25 и 1.26 об этом ничего нет.

Вместе с мегабайтами ушла вторая сторона гонки. В трейсе Go 1.24 вторую пишущую горутину можно найти грепом по строке записи в map. В этой программе это main.go:16. Она стоит в самом конце восьми тысяч строк, где‑то внутри роста таблицы, а бывает, что к моменту печати она уже ушла с этой строки на следующую. В Go 1.26 её нет вообще.

Полный вывод возвращает переменная окружения GOTRACEBACK=all. На 100 000 горутин она даёт 19,8 МБ трейса на каждое падение, а на миллионе — около 200 МБ и 21 секунду до выхода. Поведение и поменяли из‑за падения, которое забило систему сбора логов.

Вызов debug.SetTraceback("all") в коде к тому же нельзя потом понизить переменной окружения. Где горутин немного, GOTRACEBACK=all в окружении деплоя обходится дёшево, а на остальных серверах вторую сторону гонки надёжнее искать через -race, чем возвращать полный вывод.

Виновника выдаёт первый кадр вашего кода под internal/runtime/maps.fatal, в котором стоит строка операции с map. Сообщение не всегда называет реальную операцию.

for range по map при параллельной записи может упасть с concurrent map read and map write вместо «iteration», потому что после роста таблицы итератор перечитывает ключ обычным поиском. На 1.26 так было во всех прогонах, на 1.24 и 1.27 — в трети. maps.Clone в Go 1.24 падал с iteration, а в 1.26 и 1.27 у него своё сообщение: concurrent map clone and map write.

Упавший контейнер kubelet перезапускает с растущей задержкой — от 10 секунд до 5 минут. Как только контейнер поднимется заново, kubectl logs покажет уже новый экземпляр. Трейс останется в kubectl logs --previous, причём только до следующего падения. Без сборщика логов более ранние падения теряются.

‑race находит это в первом же тесте

Race detector устроен иначе, чем проверка в map, и пересечение операций во времени ему почти не нужно. Он отслеживает, есть ли между двумя доступами к памяти синхронизация, и ругается, если её нет.

Мой тест делает 20 вызовов hit() из двух горутин через httptest.

$ go test -race -count=1 .
WARNING: DATA RACE
Read at 0x00c0000ad110 by goroutine 10:
  runtime.mapaccess1_faststr()
  exp1.hit()
      /srv/main.go:33 +0xc4

Previous write at 0x00c0000ad110 by goroutine 9:
  runtime.mapassign_faststr()
  exp1.hit()
      /srv/main.go:33 +0x10a
...
--- FAIL: TestHitConcurrent (0.00s)
    testing.go:1712: race detected during execution of test

Отчёт сразу показывает обе стороны гонки, с адресом, видом доступа и стеком каждой. Без -race такой тест почти никогда не падает.

В похожей программе, где две горутины делают по 100 инкрементов, детектор map не сработал ни разу за 30 прогонов, зато в двух прогонах молча потерялось по 100 инкрементов. С -race гонка находится с первого запуска на всех трёх версиях.

Второй отчёт в том же прогоне показывает гонку на самом значении hits[key]++, ту, из‑за которой инкременты теряются молча. Глобальную map, которую трогают из обработчиков, проще всего найти до первого падения тестом, который вызывает обработчик из нескольких горутин и запускается под -race.

После такой истории хочется включить race‑сборку везде, но под продакшен‑нагрузкой она съест и процессор, и память, вплоть до OOM, который легко спутать с исходной проблемой.

Что изменилось после включения -race на исправленном мьютексом сервисе:

Метрика

Результат

Процессорное время на запрос

Увеличилось в 5,5–6 раз

Количество запросов в секунду

Снизилось в 3,2–4,3 раза

Пиковая память

Выросла с 14 до 167–179 МБ

Рост пиковой памяти

Примерно в 12 раз

Документация Go называет для типичной программы рост памяти в 5–10 раз и времени в 2–20 раз, так что память у меня вышла даже выше.

Держать такую сборку на стейдже под нагрузкой можно, если дать ей память с запасом, следить за ростом RSS, который у меня за минуту вырос со 141 до 266 МБ и на плато так и не вышел, и не мерить на ней производительность.

С GORACE=halt_on_error=1 сборка завершится с кодом 66 на первой найденной гонке, и в логах её не пропустят.

go vet здесь молчит на всех версиях. Анализатора гонок в нём нет, и статически такую ошибку стандартные инструменты не находят: из текста программы не видно, из скольких горутин будут вызывать её обработчики.

Чем заменить голую map

Обычный мьютекс убирает и падение, и потерянные инкременты, если чтение и запись идут под одной блокировкой.

Рука тянется к sync.Map, раз она «для конкурентного доступа», я тоже ждал, что на двух ядрах она выиграет.

Я сравнил бенчмарками четыре варианта:

  • обычную map под sync.Mutex;

  • её же под sync.RWMutex;

  • sync.Map;

  • и map, разбитую на 64 шарда с RWMutex.

ns/op, GOMAXPROCS=2, Go 1.26        Mutex   RWMutex   sync.Map   64 шарда
1% записей                           36.4      32.5       59.3       35.7
10% записей                          38.9      35.8       84.0       36.9
только перезапись                    40.2      59.6      254.8       62.0
постоянная смена ключей             151.0     192.8      403.6      211.7

На двух ядрах sync.Map проиграла везде: на перезаписи — в 4–6 раз, на смене ключей — в 2–2,7 раза. Сверху она добавила 2–3 аллокации на каждую запись.

Документация sync.Map сама называет два случая, под которые её оптимизировали:

  1. Ключ записывается один раз и много раз читается, как в кэше, который только растёт.

  2. Горутины пишут в непересекающиеся наборы ключей.

А чуть выше в той же документации большинству кода советуют обычную map со своей блокировкой, потому что так сохраняется типизация и проще следить, чтобы map и связанные с ней данные не расходились.

На многоядерной машине с большим числом читателей картина может поменяться, этого я не проверял.

В Go 1.24 sync.Map переписали на новую структуру. На моих двух ядрах новая версия заметно выиграла только на смене набора ключей, а на чтении разница осталась в пределах шума. Вернуться на старую через GOEXPERIMENT=nosynchashtriemap можно было только в 1.24 и 1.25, а в 1.26 старую реализацию удалили вместе со старой map.

Middleware остаётся на месте

Гонку на map рантайм замечает только по возможности и обрабатывает мимо recover() и всех defer. То, что сервис давно не падал, ещё не значит, что такой map в нём нет.

После исправления в коде останется тот же middleware с recover() и мьютекс рядом с map. Дежурный разницы, скорее всего, не заметит, разве что под больше не будет уходить в CrashLoopBackOff.

Если Go‑сервис проходит тесты, это ещё не значит, что он выдержит параллельную нагрузку: гонки могут приводить к падению приложения или незаметной потере данных. Научитесь находить такие ошибки до выхода в продакшен и разберитесь с конкурентным выполнением кода на практике.

Приходите на бесплатные демо‑уроки курса «Go‑разработчик. Базовый уровень»:

  • 5 ноября, 20:00. «Тесты в Go без боли: ловим баги раньше пользователей». Записаться

  • 23 ноября, 20:00. «Введение в горутины». Записаться