Долгий DNS resolve в Kubernetes

Эта статья посвящена проблемам работы DNS в Kubernetes, с которыми столкнулась наша команда. Как оказалось, иногда проблема лежит гораздо глубже, чем кажется изначально.

Вступление

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

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

11 часов, начало рабочего дня. В системе мониторинга не хватает части сообщений от одного из приложений.

Диагностика

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

При ближайшем рассмотрении стало понятно, что логи попадают в консоль, а вот в Elastic их уже нет.

Немного о системе мониторинга: Elasticsearch-кластер с тремя нодами, развернутый в том же Kubernetes, отображение при помощи Kibana. В Elastic логи попадали при помощи пакета Serilog.Sinks.Elasticsearch, который отправлял запросы через реверс-прокси на основе Nginx (изначально все приложения писались с расчетом на то, что в Elasticsearch не используется авторизация, так что пришлось исхищряться). Проверка логов Nginx показала, что иногда запросов от приложения вообще не поступает.

Быстрый поиск в интернете не нашел никаких похожих проблем у пользователей Serilog, зато рассказал, что у Serilog есть selflog для логирования внутренних ошибок. Недолго думая, подключаю его к самому Serilog:

Serilog.Debugging.SelfLog.Enable(msg =>
{
  Serilog.Log.Logger.Error($"Serilog self log: {msg}");
});

Делаю новый билд, запускаю релиз, проверяю логи приложения. В Kibana.

> Caught exception while preforming bulk operation to Elasticsearch: Elasticsearch.Net.ElasticsearchClientException: Maximum timeout reached while retrying request. Call: Status code unknown from: POST /_bulk

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

В этот момент возникает стойкое ощущение, что проблема кроется гораздо глубже, чем казалось изначально. В курилке обсуждаю варианты с коллегой. Коллега вспоминает, что мы до сих пор не перенесли одно API в Kubernetes, потому что запросы к нему иногда начинали занимать по 5-10 секунд вместо 100-150мс на земле. Логика его работы как раз подразумевала обращения через HTTP к сторонним сервисам. В тот раз все списали на географическую удаленность кластера от этих самых сторонних сервисов и отложили перенос до лучших времен.

Начинает вырисовываться картина – периодически, но не всегда, при выполнении HTTP запроса из контейнера запрос начинает занимать неприлично много времени.

Что бы убедиться, что проблема не привязана к конкретному приложению или фреймворку, в первом попавшемся контейнере запускаю bash-скрип, в цикле опрашивающий google.com и выводящий время запроса:

while true;
do curl -w "%{time_total}\n" -o /dev/null -s "https://google.com/";
sleep 1;
done

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

Чувствуя близость решения проблемы, собираю тестовый под:

apiVersion: v1
kind: ConfigMap
metadata:
  name: ubuntu-test-scripts
data:
  loop.sh: |-
    apt-get update;
    apt-get install -y curl;
    while true;
    do echo $(date)'\n';
    curl -w "@/etc/script/curl.txt" -o /dev/null -s "https://google.com/";
    sleep 1;
    done
  curl.txt: |-
    lookup:        %{time_namelookup}\n
    connect:       %{time_connect}\n
    appconnect:    %{time_appconnect}\n
    pretransfer:   %{time_pretransfer}\n
    redirect:      %{time_redirect}\n
    starttransfer: %{time_starttransfer}\n
    total:         %{time_total}\n
---
apiVersion: v1
kind: Pod
metadata:
  name: ubuntu-test
  labels:
      app: ubuntu-test
spec:
  containers:
  - name: test
    image: ubuntu
    args: [/bin/sh, /etc/script/loop.sh]
    volumeMounts:
    - name: config
      mountPath: /etc/script
      readOnly: true
  volumes:
  - name: config
    configMap:
      defaultMode: 0755
      name: ubuntu-test-scripts

Суть пода – в бесконечном цикле раз в секунду делаем запрос на google.com при помощи curl. Результаты запроса нас не интересуют, так что перенаправляем их в /dev/null, а в консоль выводим подробные метрики из curl.

В качестве адреса можно указать что угодно, включая сервисы, развернутые в самом кластере. Главное условие – он должен быть указан в виде доменного имени и резолвиться используемым в кластере DNS (почему именно так – далее). Конфигурация написана для Kubernetes 1.14, для других версий, возможно, потребуются небольшие изменения.

Запускаем, смотрим его логи:

Из логов видно, что основная проблема – долгий DNS-lookup, который занимает 99% времени запроса – те самые 5 секунд. Проблема может возникать как каждые два запроса, так и не проявлять себя несколько минут.

Диагноз

В очередной раз идем в интернет.

Окей, гугл — 5 seconds dns resolve kubernetes.

Гугл мгновенно выдает с десяток статей и записей в блогах, большинство из которых ссылаются на одну из двух публикаций:

• A reason for unexplained connection timeouts on Kubernetes/Docker
• 5-15s dns lookups on Kubernetes

Можно даже найти открытую issue в репозитории weave.

Из них можно узнать, что проблема:

1. Существует довольно давно (самое раннее упоминание, что я смог найти – 2017 год, но, вероятно, проблема существовала практически всегда) и до сих пор не имеет стабильно работающего решения.
2. Проявляется во внезапном росте времени DNS lookup. В некоторых случаях, задержка может доходить до 10-15 секунд.
3. Возникает, если несколько DNS-серверов доступны по одному VIP, скрытыми за DNAT.
4. Не зависит от используемого сетевого плагина.

Корень проблемы – возникновение race conditions в conntraсking механизмах Linux при использовании SNAT и DNAT. Вероятность этой проблемы Tobias Klausmann рассматривал еще в 2009 году, а в Linux 5.0 было внесено два патча, уменьшающих вероятность этого события.

Однако, в случае с Kubernetes DNS, race condition продолжают происходить.

При использовании glibc (образы на основе Ubuntu, Debian и т. д.), работает это следующим образом:

1. glibc использует один и тот же UDP сокет для параллельных запросов (A и AAAA). Так как UDP это connectionless протокол, вызов connect(2) не отправляет никаких пакетов, поэтому в таблице conntrack не создается записи.
2. DNS-сервер в Kubernetes доступен по VIP при помощи DNAT правил в iptables.
3. В процессе DNAT трансляции, ядро вызывает netfilter хуки в следующем порядке:
   a. nf_conntrack_in: создает conntrack hash object и добавляет его в список не подтвержденных записей.
   b. nf_nat_ipv4_fn: производит трансляцию и обновляет кортеж conntrack.
   c. nf_conntrack_confirm: подтверждает запись, добавляет ее в таблицу.
4. Два параллельных UDP запроса соревнуются за подтверждение записи. Дополнительно, они используют различные инстансы DNS-серверов. Один из них выигрывает гонку, второй проигрывает. Из-за этого увеличивается счетчик insert_failed, запрос теряется и уходит в таймаут.

Решение

Готового универсального решения до сих пор нет, но есть несколько возможных workaround:

1. Использовать по одному DNS-серверу на ноду и указывать его в качестве nameserver. Можно использовать LocalDNS cache
2. При использовании сетевого плагина Weave при помощи tc(8) добавить искусственную микро-задержку во все AAAA DNS запросы
3. Добавить флаг single-request-reopen в resolv.conf

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

Начиная с версии Kubernetes 1.9, в конфигурации pod появился блок dnsConfig, отвечающий за генерацию файла resolv.conf.

Добавив следующий блок в описание pod, мы заставим glibc использовать разные сокеты для A и AAAA запросов, избежав тем самым race condition.

spec:
  dnsConfig:
    options:
    - name: single-request-reopen

К сожалению, у конкретно этого метода есть одно ограничение — если приложение не использует glibc (например, это образ на основе alpine, где используется musl), то файл resolv.conf будет проигнорирован.

P.S. В нашем случае для автоматизации этого процесса был написан простейший mutating webhook, который автоматически проставляет эту секцию конфигурации для всех новых pod в кластере. Код, к сожалению, привести не могу.