Кастомные транспорты и тайм-ауты

2015-06-03

27 minute read

Перевод "Golang custom transports and timeouts".

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

TL;DR

Всегда явно задавайте тайм-ауты, особенно если вы используете кастомные транспорты.
Если вы работаете на Linux, обновите glibc на версию 2.20

"Ваш Timehop день готов"

Один из элементов работы Timehop - это утренние пуш-нотификации на телефон:

The morning push

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

Чтобы не углубляться в суть всех этих подготовок, в рамках этого поста я остановлюсь только на некоторых деталях. Самое важное:

На момент написания этого поста, мы запускаем 11 миллионов подготовок каждый день
Каждая подготовка, в среднем, занимает 300 миллисекунд
Каждая подготовка конкурентна и интенсивно использует сетевой ввод/вывод(об этом писал @kevrone в этой статье, так что вы можете оценить объем данных, с которым приходится работать)
Каждая машина конкурентно запускает 30 подготовок
У нас имеется 4 амазоновские c3.large машины
Мы используем DataDog как главную мониторилку для нашего AWS CloudFormation стека.

Ничего не предвещало беды(пока)

Когда мы перевалили за 10 миллионов проверок в день, мы начали наблюдать падения в метриках DataDog, хотя подготовки все равно продолжаются - мы наблюдаем за размером не-так-резервированной очереди альтернативным методом.

Поначалу, это случалось очень редко и мы не особо обращали на это внимание. Казалось вполне вероятным, что проблема была в рецепте для chef, который рестартовал DD агента или в самом агенте. Нам это было не очень интересно, мы просто гасили эту машину(хотя она работала, просто не общалась с DD) и CloudFormation поднимал новую. Вуаля, "пофикшено".

Но такие ситуации возникали все чаще:

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

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

Я полез смотреть логи DD:

2015-03-14 08:23:33 UTC | ERROR | dd.collector | collector(agent.py:354)
  | Uncaught error running the Agent
error: [Errno 12] Cannot allocate memory

И наши Go логи:

fatal error: out of memory (stackcacherefill)
runtime stack:
runtime.throw(0xbb7bc0)
  /usr/local/go/src/pkg/runtime/panic.c:520 +0x69
stackcacherefill()
  /usr/local/go/src/pkg/runtime/stack.c:52 +0x94

Упс.

Поиски утечки

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

После нескольких часов разбора и трассировки для каждой написанной нами go-рутины и функции, я обратил внимание на этот участок:

goroutine 281550311 [semacquire, 27 minutes]:
sync.runtime_Semacquire(0xc2267cadc0)
  /usr/local/go/src/pkg/runtime/sema.goc:199 +0x30
sync.(*WaitGroup).Wait(0xc2337c8f80)
  /usr/local/go/src/pkg/sync/waitgroup.go:129 +0x14b
net.(*singleflight).Do(0xbbdc50, 0xc22f602e40, 0x20, ...)
  /usr/local/go/src/pkg/net/singleflight.go:37 +0x127
net.lookupIPMerge(0xc22f602e40, 0x20, 0x0, 0x0, 0x0, 0x0, 0x0)
  /usr/local/go/src/pkg/net/lookup.go:42 +0xae
net.func·025()
  /usr/local/go/src/pkg/net/lookup.go:80 +0x3e
created by net.lookupIPDeadline
  /usr/local/go/src/pkg/net/lookup.go:82 +0x2d8

Количество аналогичных блоков в файле, а также время, на которой go-рутина залипала (около 30 минут) мне показалось достаточно странным, я решил подсчитать количество аналогичных записей в логе...

$ grep 'net.lookupIPDeadline' crash.log | wc -l
420563

Ого. Очень много зависших лукапов.

Но они все работают до определенного дедлайна и чистят за собой, правильно?

Ничуть. Вот код lookupIPDeadline:

// lookupIPDeadline ищет имя хоста с учетом определенного дедлайна.
func lookupIPDeadline(host string, deadline time.Time)
                     (addrs []IPAddr, err error) {
    if deadline.IsZero() {
        return lookupIPMerge(host)
    }

    // Мы могли бы передать дедлайн ниже, передав его в 
    // функцию поиска. Но наиболее часто используется 
    // реализация, вызывающая getaddrinfo без всяких тайм-аутов.
    timeout := deadline.Sub(time.Now())
    if timeout <= 0 {
        return nil, errTimeout
    }
    t := time.NewTimer(timeout)
    defer t.Stop()

    ch := lookupGroup.DoChan(host, func() (interface{}, error) {
        return lookupIP(host)
    })

    select {
    case <-t.C:
        // Время работы определения DNS истекло по некоторым причинам.
        // Следующий запрос  запустил определение DNS не дожидаясь
        // завершения текущего определения. Смотрите issue 8602.
        lookupGroup.Forget(host)

        return nil, errTimeout

    case r := <-ch:
        return lookupIPReturn(r.v, r.err, r.shared)
    }
}

Несколько интересных замечаний:

Если параметр deadline не определен, то нет гарантий, что функция что-то вернет.
Когда параметр deadline определен, то это только тайм-аут в Go и нет никаких более низкоуровневых тайм-аутов(на уровне ОС).
Обратите внимание на упомянутую проблему #8602, к которой мы вернемся позже.

Я был удивлен отсутствием какого-либо низкоуровневого тайм-аута, при выполнении поиска DNS... Давайте заглянем внутрь lookupIPMerge:

func lookupIPMerge(host string) (addrs []IP, err error) {
    addrsi, err, shared :=
        lookupGroup.Do(host, func() (interface{}, error) {
            return lookupIP(host)
        })
    // ...

В этом месте функция lookupIP платформо-зависимая. В моем случае она определена в файле lookup_unix.go (бинарник запускается на Linux машине).

func lookupIP(host string) (addrs []IP, err error) {
  addrs, err, ok := cgoLookupIP(host)
  if !ok {
    addrs, err = goLookupIP(host)
  }
  return
}

Функция cgoLookupIP (которая использует cgoLookupIPCNAME) определена в файле cgo_unix.go

На всем нашем пути в недра кода никакие тайм-ауты не встречаются. Посмотрите на документацию getaddrinfo, никакого упоминания про тайм-ауты.

В принципе, если вызывается lookupIP(host) из DoChan() этой lookupGroup(что, судя по названию, и происходит), то такое поведение заблокирует go-рутину навсегда. Все, до свидания.

Единственный способ исправить ситуацию, это пробрасывать тайм-аут ниже по стеку. На этом месте вернемся к проблеме #8602 и в коммите почитаем вот это туду:

// TODO(bradfitz): рассмотреть пробрасывание дедлайна ниже,
// в функцию поиска имени. Но это предполагает переписывание
// для нативного Go, cgo, Windows и так далее.

И в результате это было заменено на:

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

Да, вы прочитали все правильно:

getaddrinfo у которой нет никаких тайм-аутов.

В конце концов, единственный вариант пофиксить утечку, это реализация getaddrinfo с каким-то жестким лимитом на время работы DNS лукапа и выходом по истечению этого лимита.

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

В нашем случае это был баг getaddrinfo из glibc, который пофиксили в версии v2.20, поэтому единственным решением было обновить версию glibc.

Так можно проверить какая версия glibc используется в вашей системе(в случае с Linux):

$ ldd --version
ldd (Ubuntu EGLIBC 2.19-0ubuntu6) 2.19

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

Используйте явные тайм-ауты везде

Когда вы кодите что-то вроде такого...

foo := &http.Transport{}

... то использование этого транспорта может завесить на неопределенный срок выполнение лукапа и/или TLS рукопожатия.

В случае незашифрованных соединений, инстанс Transport для установления соединения будет использовать функцию, указанную в поле Dial. Если функция не указана, то по умолчанию будет использоваться net.Dial, которая создает временный Dialer, который может иметь или не иметь тайм-аут(ключевая мысль, что все таки может).

И так как вы, скорее всего, будете использовать этот транспорт совместно с http.Client, то рекомендую устанавливать значение для поля Timeout. Имейте ввиду, что достаточно сложно реализовать глобальный тайм-аут для всего цикла запроса(установка соединение, отправка запрос и разбор ответа).

Я поднялся вверх по стеку вызовов(уже к нашему коду) и обнаружил вот это:

client := &http.Client{
    Transport: &http.Transport{},
}

Этот код был прям на второй строчкое. Быстрое и не очень красивое исправление проблемы - просто заменить &http.Transport{} на &http.DefaultTransport. Но можно пойти более правильным(для продакшен систем) путем:

secs := 3 // довольно агрессивно
client := &http.Client{
    Transport: &http.Transport{
        Proxy: http.ProxyFromEnvironment,
        Dial: (&net.Dialer{
            Timeout:   secs * time.Second,
            KeepAlive: 30 * time.Second,
        }).Dial,
        TLSHandshakeTimeout: secs * time.Second,
    },
}

Заключение

Используйте явные тайм-ауты везде, где это возможно.
http.DefaultClient относительно безопасный, так как использует http.DefaultTransport, у которого предустановленны тайм-ауты на соединение(хотя и нет тайм-аутов на запросы, поэтому используйте осторожно).
Убедитесь, что ваша Dial функция в http.Client имеет определенные тайм-ауты и устанавливает TLSHandshakeTimeout.
Обновите glibc до версии 2.20 или выше.