Горе главата, преместихме се! Ако искате да продължите да сте в крак с най-новото техническо съдържание от Square, моля, посетете ни в нашия нов дом https://developer.squareup.com/blog

Това е историята на изтичане на ресурси в една от услугите Go на Square и процеса на разкриване на първопричината. Изправени пред остри и мистериозни системни показатели, ние използвахме различни стандартни и домашни инструменти, за да разкрием фин бъг в една от нашите основни вътрешни рамки.

По-рано тази година една от нашите Go услуги започна да използва значително повече памет, излизайки от стабилно състояние на използване на плоска памет и предвидими модели за събиране на боклук. В същото време използването на процесора също се увеличи. Тази конкретна услуга обикновено използва около 200 MB памет, но тази цифра скоро нарасна до няколко GB.

След продължително разследване се оказа, че за значителен брой заявки комбинация от грешки е карала услугата да запазва метаданните за всяка заявка за почти 17 часа вместо няколко милисекунди. В крайна сметка имаше две основни причини, като и двете бяха предизвикани от привидно безобидна конфигурационна грешка в друга услуга. Докато само една услуга беше засегната, много от другите ни услуги на Go бяха потенциално податливи на тази грешка.

Тази публикация първо обяснява грешката, която срещнахме, след което разказва различните стъпки, които предприехме, за да разследваме, някои от които бяха по-плодотворни от други.

Основна причина и извлечени уроци

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

Тази основна причина беше предизвикана от промяна на конфигурацията в друга услуга, която по невнимание зададе времето за изчакване на клиентската заявка на 60 000 секунди вместо планираните 60 000 милисекунди. Тази неправилна конфигурация на клиента доведе до това, че всяка от неговите заявки има своите Contexts, задържани от сървъра с грешки за 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

Връзките между Contexts в примера изглеждат така:

В допълнение към съхраняването на данни за ключ-стойност, Context могат също да бъдат създадени със свързани крайни срокове за стенен часовник. Когато се създаде Context с краен срок, той регистрира функция за обратно извикване, която маркира контекста като отменен след изтичане на крайния срок. Тази функция за обратно извикване е планирана от вътрешните елементи на Go runtime.

// 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. Експериментирайте с различни кръпки на canary хостове, като използвате куки GC по време на изпълнение, за да стесните кои обекти се запазват.
  6. Поправи се!

Четвъртата и петата стъпка изискваха най-много хакване, но в крайна сметка бяха най-плодотворни.

Стъпка 1: Търсене на корелиращи промени

Първо направихме списък с наблюдаваните промени:

  • Внезапно нарастване на използването на паметта от под 200 MB до 3–6 GB.
  • Използването на паметта се покачва последователно, но като че ли е на плато. Процесът не изчерпваше паметта и не беше убит от операционната система. Погледнато назад, това има много смисъл, тъй като изтеклите обекти в крайна сметка бяха GCed, когато техните Context таймери за почистване се задействаха след 17 часа.
  • Предсказуемата преди това скорост на GC намаля значително.
  • Постоянно по-високо използване на процесора.

Направихме и списък с това, което не се е променило:

  • Нямаше скок в заявките към услугата.
  • Няма скорошни внедрявания на услугата.
  • Няма корелиращи внедрявания на услуги, които са зависимости.
  • Няма корелиращи внедрявания на услуги за повикване. Това наблюдение беше неправилно, тъй като промяната на времето за изчакване на клиента в крайна сметка корелира.

Стъпка 2: Ровене в регистрационните файлове на GC

Тъй като видяхме тревожни модели на GC, решихме да започнем с преглед на регистрационните файлове на GC, за да открием някакво странно поведение. Основният извод от четенето на тези регистрационни файлове беше, че въпреки нашата купчина непрекъснато растяща, събирането на боклука не отнемаше много време; всяко изпълнение на 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% от общото време на процеса е прекарано в GC.
  • 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 MB от разпределените 2504 MB купчина са използвани от Go обекти.
  • 3818 MB goal: Размерът на купчината, при който събирачът на отпадъци ще започне следващото изпълнение. Това се определя от размера на купчината след текущото изпълнение на GC и променливата на средата GOGC, която има стойност по подразбиране 100 и представлява съотношението на новоразпределените данни към съществуващите данни след последния GC. Изчислението зад целта в този случай: 1908 MB + (1908 MB * GOGC / 100) ≈ 3818 MB.
  • 2: брой процесори, използвани от събирача на отпадъци.

Имаше и някои допълнителни регистрационни файлове от чистача на боклукчия:

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

Чистачът освобождава неизползваната памет обратно в системата, като наистина освобождава памет.

Нека интерпретираме изхода на чистач:

  • 0 MB released: В системата не беше върната памет.
  • inuse: 2543: Go е разпределил 2543 MB памет за своята купчина, която може да включва неизползвана памет и мъртви обекти.
  • idle: 339: 339 MB памет, която преди съдържаше достъпни обекти, но вече не.
  • sys: 2883: 2883 MB са поискани от ОС.
  • released: 186: 186 MB памет са освободени обратно към операционната система.
  • consumed: 2696: 2696 MB са разпределени за 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 MB (6,82% от купчината) обекти, които все още са достъпни. Освен това, handleRequest плюс методите, достъпни от него, държат 1,4 GB обекти. В нормално състояние и двете числа биха били най-много няколко десетки MB.

Когато за първи път видяхме тези данни, правилно предположихме, че кодът за обработка на заявки изпуска обекти. Също така забелязахме, че въпреки запазването на много Context обекти, съобщенията за заявка не се запазват. На този етап обаче все още не разбираме първопричината. Погледнато назад, бихме могли също да отбележим, че 94 MB памет, разпределена вътре в time.AfterFunc, е необичайно и да проучим това допълнително.

Стъпка 4: Анализ на дъмп на паметта

В този момент решихме да излезем от утъпкания път.

Въпреки че pprof ни подсказа, че данните за заявка Context изтичат, той не посочи точно причината за изтичането и какво се държи в тях. Много езици имат инструменти за изхвърляне на купчината на приложението и за анализиране и преминаване през обектната графика - ако това беше приложение на Java, с радост щяхме да задействаме например „Eclipse Memory Analyzer“. За съжаление, Go не е един от тези езици.

Поддръжката на Rich heap dump е невероятно полезна. Това прави много по-лесно да откриете защо даден обект не се събира боклук, като преминете по пътя от запазен обект до основен обект. В този случай искахме да намерим структура от данни, която да държи тонове данни, свързани със заявки, и подозирам, че наличието на истински инструмент за анализатор на купчина би намалило драстично времето, необходимо ни за отстраняване на грешки.

Въпреки че 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 се появява в купчината 995 090 пъти.

# 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, за да помогнем и най-накрая разбрахме всичко.

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

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 не са GCed, но че обектите на заявка са. Броят на неизплатените Context продължава да расте. Във фрагмента по-долу от 162 573 Contexts, разпределени по време на живота на процеса, 4 920 остават в паметта.

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

Сглобяване на всичко

До този момент знаехме, че Contexts изтичат и къде се създават тези Contexts. Препрочетохме документацията на 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 и екосистемата на инструментите около тях.