Внимание, мы переехали! Если вы хотите и дальше следить за последними техническими новостями Square, посетите наш новый дом https://developer.squareup.com/blog

Это история утечки ресурсов в одном из сервисов Square’s Go и процесс выявления первопричины. Столкнувшись с острыми и загадочными системными показателями, мы использовали различные стандартные и самодельные инструменты, чтобы выявить тонкую ошибку в одной из наших основных внутренних структур.

Ранее в этом году один из наших сервисов Go начал использовать значительно больше памяти, выйдя из устойчивого состояния плоского использования памяти и предсказуемых шаблонов сборки мусора. В то же время возросла и загрузка ЦП. Эта конкретная служба обычно использовала около 200 МБ памяти, но вскоре эта цифра выросла до нескольких ГБ.

После долгого расследования выяснилось, что для значительного количества запросов комбинация ошибок заставляла службу сохранять метаданные каждого запроса в течение почти 17 часов вместо нескольких миллисекунд. В конечном итоге было две основные причины, обе из которых были устранены кажущейся безобидной ошибкой конфигурации в другом сервисе. Хотя затронута была только одна служба, многие другие наши службы Go были потенциально подвержены этой ошибке.

В этом посте сначала объясняется обнаруженная нами ошибка, а затем излагаются различные шаги, которые мы предприняли для расследования, некоторые из которых были более плодотворными, чем другие.

Основная причина и извлеченные уроки

В конечном итоге основная причина заключалась в неправильном использовании типа Context в Go. В Square у нас есть настраиваемая структура для обработки входящих запросов и отправки их функциям обработчика. Этот код фреймворка создавал Contexts с крайними сроками, но после выполнения запроса не отменял Contexts для освобождения связанных ресурсов. Это привело к тому, что время жизни каждого Context объекта в куче превысило время жизни соответствующего запроса.

Эта основная причина была вызвана изменением конфигурации в другой службе, которая непреднамеренно установила тайм-аут клиентского запроса на 60 000 секунд вместо предполагаемых 60 000 миллисекунд. Эта неправильная конфигурация клиента привела к тому, что каждый из его запросов имел свои Context на неисправном сервере в течение 60 000 секунд (16,7 часа) вместо нескольких миллисекунд.

Контекст Go: краткое руководство

В Go Context - это интерфейс, используемый как общий способ передачи неизменяемых метаданных для одного запроса или операции.

Context создается с помощью пары "ключ-значение" и может быть заключен в другой Context для добавления или переопределения данных. Внешний / обернутый / дочерний Context имеет доступ к своим обернутым / родительским Context данным, но не наоборот.

Вот краткий пример того, как создаются Context:

rootCtx := context.Background() // Returns a singleton
// a is a child of rootCtx
a := context.WithValue(rootCtx, "location", "San Francisco") 
// b is a child of a
b := context.WithValue(a, "weather", "foggy")
// c is also a child of a and is unrelated to b
c := context.WithValue(a, "weather", "cloudy")
// d is a child of c and overrides c's "weather" value
d := context.WithValue(c, "weather", "sunny")
 
fmt.Printf("location=%v weather=%v\n",
    a.Value("location"), a.Value("weather"))
fmt.Printf("location=%v weather=%v\n",
    b.Value("location"), b.Value("weather"))
fmt.Printf("location=%v weather=%v\n",
    c.Value("location"), c.Value("weather"))
fmt.Printf("location=%v weather=%v\n",
    d.Value("location"), d.Value("weather")) 
 
// Output:
location=San Francisco weather=<nil>
location=San Francisco weather=foggy
location=San Francisco weather=cloudy
location=San Francisco weather=sunny

Отношения между Context в примере выглядят следующим образом:

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

// context.WithTimeout schedules a timer to cancel the context.
// The deadline for ctx will be the 5 seconds from the current
// wall clock time.
ctx, cancelCtx := context.WithTimeout(
    context.Background(), 5*time.Second)
defer cancelCtx()
// ... some amount of time passes ...
if ctx.Err() == nil {
    fmt.Println("The context is not done yet.")
    // ... do work ...
} else {
    // The context either timed out or cancelCtx() was called.
    fmt.Println("The context is done. Skipping work.")
}

Что особенно важно, функция обратного вызова таймера сохраняет ссылку на Context, который нужно отменить. Если код приложения не отменяет явно Context, таймер времени выполнения остается установленным, а Context остается в памяти до срабатывания таймера.

Это была наша основная проблема: часть нашего кода фреймворка явно не отменяла Context, которые он создавала и передавала коду обработчика.

Чтобы проиллюстрировать, код фреймворка, по сути, делал это:

func (s *Server) handleRequest(req *Request, conn *Connection) {
    // Create a context with a deadline an hour in the future.
    ctx, _ := context.WithTimeout(context.Background(), 1*time.Hour)
    // Attach metadata to the ctx using a helper function.
    ctx = s.contextWithMetadata(ctx, req)
    // Deserialize the request and delegate to a handler.
    reqProto := deserialize(req)
    if respProto, err := s.callHandler(ctx, reqProto); err != nil {
        conn.WriteError(err)
    } else {
        conn.WriteResponse(respProto)
    }
    // Even though this method returns quickly, ctx is retained
    // in memory for an hour since the pending deadline timer holds
    // a reference to it. Only after the timer fires can the ctx
    // be garbage collected.
}

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

Учитывая приведенный выше фрагмент кода с ошибкой, фактическое исправление кода просто:

func (s *Server) handleRequest(req *Request, conn *Connection) {
    // Create a context with a deadline an hour in the future.
    ctx, cancelCtx :=
        context.WithTimeout(context.Background(), 1*time.Hour)
    // Use defer in case of panics or returning early.
    defer cancelCtx()
    // ... The rest of the method is the same ...
    // Right after this method returns, cancelCtx() is called,
    // allowing ctx to be garbage collected.
}

Дополнительное чтение: реализация Context использует timer.AfterFunc для планирования таймера крайнего срока и метод timer.(*Timer).Stop для очистки этого таймера при отмене Context. Взгляните на исходный код context.go, чтобы увидеть, как таймер создается и используется.
Внутренне среда выполнения Go использует кучу для управления всеми невыполненными таймерами. См. Исходный код runtime / time.go для его реализации.

Уроки выучены

Всегда откатывайте, когда это возможно. Это был не столько усвоенный урок, сколько игнорируемая максима. Когда мы начали исследовать эту проблему, мы в первую очередь искали другие изменения, которые происходили примерно в то же время, когда снижалась производительность. Хотя в течение нескольких дней произошло несколько интересных изменений, изменение конфигурации тайм-аута клиента имело очень хорошую корреляцию с точки зрения времени. Несмотря на то, что несколько инженеров просматривали изменения конфигурации в рамках первоначальной проверки и снова во время этого расследования, все отклонили их как несущественные («мы просто немного увеличили время ожидания - ничего страшного!»).

Учитывая близкое время между изменением и инцидентом, а также очень низкую стоимость отката изменения конфигурации клиента, мы должны были немедленно откатить изменение тайм-аута. Это не устранило бы основную причину, но помогло бы точно определить, где проводить дальнейшие исследования.

Пробелы в инструментах Go затрудняли расследование. Отладке этой проблемы мешал заметный пробел в инструментах Go, с которым мы не столкнулись бы, если бы наш код работал на JVM. Все признаки указывают на то, что эта проблема является довольно классической утечкой памяти, но у Go на самом деле нет инструментов для дампа и анализа кучи. Хотя инструмент pprof может быть полезен для поиска некоторых проблем с памятью и дает некоторые полезные советы в этом случае, он ограничен: он дает статистику о том, где размещены объекты, но не о том, что их сохраняет.

Расследование

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

В целом прогресс был следующим.

  1. Ищите корреляцию изменений кода и среды в затронутых системах, связанных с ними системах и оборудовании.
  2. Покопайтесь в журналах GC.
  3. Профилируйте кучу с помощью pprof.
  4. Попытайтесь провести более глубокий анализ кучи, используя методы дампа кучи времени выполнения и собственные инструменты.
  5. Поэкспериментируйте с различными патчами на канареечных хостах, используя обработчики мусора во время выполнения, чтобы сузить круг сохраняемых объектов.
  6. Исправить!

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

Шаг 1: поиск коррелирующих изменений

Сначала мы составили список наблюдаемых изменений:

  • Внезапное увеличение использования памяти с менее 200 МБ до 3–6 ГБ.
  • Использование памяти постоянно росло, но, похоже, стабилизировалось. Процесс не исчерпал память и не был остановлен ОС. В ретроспективе это имеет большой смысл, поскольку объекты, в которых произошла утечка, в конечном итоге собирались в сборщик мусора, когда их Context таймеры очистки сработали через 17 часов.
  • Ранее предсказуемая скорость работы сборщика мусора значительно снизилась.
  • Постоянно более высокая загрузка ЦП.

Мы также составили список того, что не изменилось:

  • Пика запросов в сервис не было.
  • В последнее время служба не развертывалась.
  • Нет коррелирующих развертываний сервисов, которые являются зависимостями.
  • Нет коррелирующих развертываний телефонных служб. Это наблюдение было неверным, так как изменение тайм-аута клиента в конечном итоге коррелировало.

Шаг 2. Изучение журналов GC

Поскольку мы увидели тревожные паттерны сборки мусора, мы решили начать с просмотра журналов сборки мусора, чтобы найти какое-либо странное поведение. Главный вывод из чтения этих журналов заключался в том, что, несмотря на то, что наша куча постоянно увеличивалась, сборка мусора не занимала слишком много времени; каждый запуск GC был коротким и высвобождал только небольшой объем памяти.

Кроме того, этот шаг был полезным упражнением для лучшего понимания формата журнала сборщика мусора Go, поэтому давайте взглянем на отрывок из того, с чем мы столкнулись:

GC forced
gc 848 @78217.082s 0%: 0.050+6819+3.3 ms clock, 0.10+0/3412/9164+6.6 ms cpu, 2474->2504->1908 MB, 3818 MB goal, 2 P

Вот как интерпретировать компоненты первой gc строки:

  • 848: Это была 848-я сборка мусора с момента запуска процесса.
  • 78217.082s: В этот момент процесс выполнялся 78217,082 секунды.
  • 0%. Примерно 0% общего времени процесса было потрачено на сборку мусора.
  • 0.050+6819+3.3 ms clock, 0.10+0/3412/9164+6.6 ms cpu: время, затрачиваемое на каждую из трех фаз GC: остановка мировой развертки, одновременная метка и сканирование и завершение остановки мировой метки.
  • 2474->2504->1908 MB: размеры кучи до GC и после GC, а также размер активной кучи. Go увеличивает доступность кучи, поэтому в этом случае только 1908 МБ из выделенных 2504 МБ кучи использовалось объектами Go.
  • 3818 MB goal: размер кучи, при котором сборщик мусора начнет следующий запуск. Это определяется размером кучи после текущего запуска сборщика мусора и переменной среды GOGC, которая имеет значение по умолчанию 100 и представляет собой отношение вновь выделенных данных к существующим данным с момента последнего запуска сборщика мусора. Расчет цели в данном случае: 1908 МБ + (1908 МБ * GOGC / 100) ≈ 3818 МБ.
  • 2: количество процессоров, используемых сборщиком мусора.

Были также некоторые дополнительные журналы от мусорщика сборщика мусора:

scvg521: 0 MB released
scvg521: inuse: 2543, idle: 339, sys: 2883, released: 186, consumed: 2696 (MB)

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

Давайте интерпретируем вывод мусорщика:

  • 0 MB released: В систему не возвращена память.
  • inuse: 2543: Go выделил 2543 МБ памяти для своей кучи, которая может включать неиспользуемую память и мертвые объекты.
  • idle: 339: 339 МБ памяти, которая раньше содержала доступные объекты, но больше не хранится.
  • sys: 2883: от ОС запрошено 2883 МБ.
  • released: 186: 186 МБ памяти возвращено ОС.
  • consumed: 2696: 2696 МБ выделено для Go ОС.

Шаг 3. Профилирование кучи с помощью pprof

Имея доказательства утечки памяти, мы решили использовать pprof, чтобы сузить, какой код вызывает утечку памяти. Pprof - это стандартный инструмент Go для создания дампа, изучения и визуализации статистики использования памяти и ЦП приложениями Go. С помощью pprof вы можете анализировать один дамп или разницу между двумя разными дампами. Последнее полезно для поиска изменений после того, как приложение работает в устойчивом состоянии.

Наши приложения Go имеют внутренние конечные точки HTTP для получения данных для pprof, поэтому мы использовали их для получения дампа запущенного процесса:

curl -sk https://our-service:12345/debug/pprof/heap > heap.out

Когда у нас был дамп, мы смогли использовать pprof, чтобы показать, какие методы распределяют больше всего данных. Вот одна из запущенных нами команд, которая отображает функции, выделяющие наиболее невыделенную память.

# pprof takes both the binary of the app (service_binary in this
# case) and the dump (heap.out) as arguments.
go tool pprof -runtime --inuse_space service_binary heap.out

(pprof) top
1473.20MB of 1884.53MB total (78.17%)
Dropped 1264 nodes (cum <= 9.42MB)
Showing top 10 nodes out of 77 (cum >= 73.50MB)
flat  flat%   sum%        cum   cum%
286.02MB 15.18% 15.18%   561.10MB 29.77%  context.WithDeadline
242.57MB 12.87% 28.05%   524.09MB 27.81%  square/up/xp/sakeutil.NewClientContextWithTimeout
224.52MB 11.91% 39.96%   224.52MB 11.91%  square/up/tracing.appendTiming
152.01MB  8.07% 48.03%   152.01MB  8.07%  runtime.rawstringtmp
128.54MB  6.82% 54.85%  1444.29MB 76.64%  square/up/sake/server.(*Server).handleRequest
122.02MB  6.47% 61.32%   122.02MB  6.47%  square/up/vendor/stash.corp.squareup.com/go/protobuf.git/proto.(*Buffer).DecodeRawBytes
85.51MB  4.54% 65.86%    87.07MB  4.62%  runtime.mapassign1
80MB     4.25% 70.11%    93.56MB  4.96%  time.AfterFunc
78.51MB  4.17% 74.27%   182.02MB  9.66%  context.WithCancel
73.50MB  3.90% 78.17%    73.50MB  3.90%  context.WithValue

Каждая из этих строк указывает, сколько памяти было использовано объектами, созданными внутри конкретной функции. Однако важно отметить, что это указывает только на то, где были созданы объекты, а не на то, что все еще сохраняет ссылки на них.

Если присмотреться, то метод, обрабатывающий все входящие запросы, по крайней мере косвенно отвечает за множество сохраненных объектов:

128.54MB  6.82% 54.85%  1444.29MB 76.64%  square/up/sake/server.(*Server).handleRequest

Эта строка указывает, что handleRequest создал 128 МБ (6,82% кучи) объектов, которые все еще доступны. Кроме того, handleRequest плюс доступные из него методы содержат 1,4 ГБ объектов. В нормальном состоянии оба этих числа не превышают нескольких десятков МБ.

Когда мы впервые увидели эти данные, мы правильно предположили, что в коде обработки запроса происходит утечка объектов. Мы также заметили, что, несмотря на сохранение большого количества Context объектов, сообщения запроса не сохранялись. Однако на этом этапе мы все еще не понимали первопричину. Оглядываясь назад, мы могли бы также отметить, что 94 МБ памяти, выделенной внутри time.AfterFunc, необычно, и исследовать это подробнее.

Шаг 4: Анализ дампа кучи

В этот момент мы решили пойти по проторенной дороге.

Хотя pprof намекнул на утечку Context данных по запросу, он не указал причину утечки и то, что за ними держалось. Во многих языках есть инструменты для сброса кучи приложения, анализа и обхода графа объектов - если бы это было приложение Java, мы бы с радостью запустили, например, Eclipse Memory Analyzer. К сожалению, Go не относится к таким языкам.

Богатая поддержка дампа кучи невероятно полезна. Это значительно упрощает поиск причины, по которой объект не собирается сборщиком мусора, пройдя путь от сохраненного объекта к корневому объекту. В этом случае мы хотели найти структуру данных, в которой хранятся тонны данных, связанных с запросами, и я подозреваю, что наличие настоящего инструмента анализа кучи значительно сократило бы время, необходимое для отладки.

Хотя Go не поддерживает исследование кучи, в пакете runtime/debug есть неофициальный метод создания чего-то примерно наподобие дампа кучи: debug.WriteHeapDump. Эта функция выводит некоторое низкоуровневое состояние кучи запущенного процесса в двоичном формате. В вики Golang есть неполная документация по формату, поэтому нам пришлось прочитать WriteHeapDump исходный код, чтобы понять его.

У вывода WriteHeapDump есть огромный недостаток: он по существу выгружает необработанные байты каждого объекта вместе с набором битов, указывающим, какие слова в этих байтах представляют указатели на другие объекты. Он опускает какие-либо данные о типе, включая имя типа.

Обход графа объектов без типов был в лучшем случае утомительным и невозможным в большинстве случаев. Мы обнаружили, что поиск очевидных строк и работа в обратном направлении через ссылающиеся объекты - единственный способ определить типы объектов. Даже для этого требовалось знание того, как Go представляет основные структуры данных, такие как срезы и карты, в памяти.

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

Вот как выглядит сброшенный объект. Каждая строка поля ниже представляет собой слово памяти, а некоторые ссылки на другие объекты, когда слово представляет собой указатель.

Изображение выше взято из проекта с открытым исходным кодом heapdump14, который был написан примерно для Go 1.4. Старые среды выполнения Go включали в кучу более подробную информацию о типах, но количество доступных метаданных было уменьшено по мере развития среды выполнения в новых версиях Go. Мы решили попробовать использовать этот инструмент, чтобы лучше понять граф объектов кучи; Для его запуска требовалось применить этот патч к исходному тексту инструмента, а затем написать дополнительный собственный патч.

После обхода графика, просматриваемого через heapdump14, мы определили, что объект на изображении выше был экземпляром типа, который выглядит следующим образом:

type SomeProtoMessage struct {
    FirstField       *string
    SomeBytes        []byte
    XXX_unrecognized []byte
}

«64_PPSSP» на изображении - это имя типа в heapdump14. Номер выбирается инструментом случайным образом, но он уникален для данного типа. PPSSP указывает типы каждого слова в объекте: [указатель, указатель, скаляр, скаляр, указатель]. На изображении выше объект состоит из 7 слов, где каждая строка поля представляет слово. Это не 5, предложенная PPSSP; неясно, как было сформировано это имя или почему выгруженный тип содержит 7 слов вместо ожидаемых 3 (одно для указателя и два для фрагментов).

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

Шаг 4 1/2: не все потеряно

Хотя пересечение кучи в конечном итоге было неудачным, попытка не обернулась полным провалом. Мы заметили, что строки в куче были полезными подсказками о сохранении некоторых типов - особенно полезными в нашем случае, поскольку запросы к серверу содержат много строк.

Имея это в виду, мы написали простой инструмент для извлечения количества общих строк в куче. Он также подсчитывает строки в отдельном формате, который платформа RPC Square использует для представления идентификаторов запросов.

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

Первая строка вывода показывает количество идентификаторов запросов в куче, указывая, сколько запросов имеют некоторые связанные данные, которые все еще находятся в памяти.

Остальные строки сначала выводят счетчик, затем (p), если счетчик предназначен для строки, закодированной в сообщении буфера протокола, и, наконец, саму строку, окруженную обратными кавычками. Например, 995090 (p) `application/x-protobuf` означает, что строка буфера протокола application/x-protobuf появляется в куче 995090 раз.

# Each request has a unique string ID in a uniform format.
# The following count shows lots of request ID strings in the heap.
Request ID counts: 1492947
# The format of each following line is:
# count [(p) if protocol buffer string] `string in heap`
995090 (p)     `application/x-protobuf`
# Although the service has many different callers, only the name of
# the service with the misconfigured timeout shows up a lot.
497548         `the-misconfigured-calling-service`
497545 (p)     `Content-Length`
497545 (p)     `Accept`
# The bad timeout value included in requests.
497545 (p)     `60000`
497545 (p)     `X-Request-Deadline`

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

Шаг 5. Экспериментируйте с финализаторами

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

Чтобы определить характеристики конкретных сохраняемых объектов, мы обратились к функции Go runtime.SetFinalizer. Эта функция инструктирует среду выполнения Go выполнить обратный вызов непосредственно перед сборкой мусора для объекта. Настроить обратный вызов очень просто, хотя я бы не рекомендовал использовать его в реальном производственном коде:

heapObject := new(string)
runtime.SetFinalizer(heapObject, func(theObject *string) {
    // heapObject/theObject is about to be garbage collected.
    fmt.Println("bye!")
})

Помня о SetFinalizer, мы установили финализаторы для небольшого набора типов и попросили наш сервер время от времени регистрировать счетчики каждого созданного типа и сбора мусора. Код для отслеживания Contexts выглядел примерно так:

var (
    contextNumber       int64
    contextsOutstanding int64
)
func requestHandler(...) {
    ctx, _ := context_helper.NewContext(timeout)
    // To help debug, use a counter to link allocation and
    // and finalizer log messages.
    ctxNumber := atomic.AddInt64(&contextNumber, 1)
    // Keep a count of reachable Context objects.
    ctxOutstanding := atomic.AddInt64(&contextsOutstanding, 1)
    glog.Infof("gc-investigation: action=alloc type=Context " +
       "id=%d outstanding=%d",
       ctxNumber, ctxOutstanding)
    runtime.SetFinalizer(ctx, func(r context.Context) {
        ctxOutstanding := atomic.AddInt64(&contextsOutstanding, -1)
        glog.Infof("gc-investigation: action=finalize " +
            "type=Context id=%d outstanding=%d",
            ctxNumber, ctxOutstanding)
    })
    // ...
}

Вывод этого журнала недвусмысленно показал, что someContexts не собирались в сборку мусора, но объекты запроса были. Количество выдающихся Context продолжало расти. В приведенном ниже фрагменте из 162 573 Context, выделенных в течение жизненного цикла процесса, 4920 остались в памяти.

2017-04-21 23:42:21,919257 INFO [4] [server.go:635] gc-investigation: action=finalize type=Context id=162573 outstanding=4920

Собираем все вместе

К этому моменту мы знали, что утечки Context и где эти Context создавались. Мы перечитали Context документацию и просмотрели ее исходный код, чтобы лучше понять, как она реализована. Это привело нас к тому, что мы увидели использование time.AfterFunc и то, как это взаимодействует со средой выполнения. Затем мы сформулировали гипотезу, что эти обратные вызовы таймера не работают. Вскоре это было подтверждено более тщательным чтением исходного кода нашей серверной инфраструктуры.

В конце концов, исправление было невероятно простым изменением нашего кода фреймворка обработчика запросов:

// Before
func requestHandler(...) {
    ctx, _ := context_helper.NewContext(timeout)
    // ...
}
// After
func requestHandler(...) {
    ctx, cancelCtx := context_helper.NewContext(timeout)
    defer cancelCtx() // <-- Oops!
    // ...
}

Это устранило проблему, которую мы наблюдали в нашем некорректном сервисе. Поскольку фреймворк используется другими внутренними приложениями Go, исправление также защищает их от некорректного поведения клиентов.

Оглядываясь назад

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

Во-первых, соглашения Go о том, что не следует игнорировать возвращаемые ошибки и функции очистки, существуют по уважительной причине и не должны игнорироваться случайно. Исходный код фреймворка не должен игнорировать CancelFunc, связанный с Contexts, поскольку в Context документации четко указано, что он освобождает ресурсы. Я бы сказал, что любой код, поглощающий значения очистки и возврата ошибок, является исключительным и должен иметь четко задокументированное обоснование.

Еще одна практика - без колебаний откатить код, если он тесно коррелирует с проблемой в связанной системе. Стоимость этого очень мала, но может помочь сузить количество триггеров ошибки. В этом конкретном случае мы значительно сэкономили бы время на отладку.

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