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

Здесь в Skroutz в составе нашего стандартного набора инструментов мы обеспечиваем каждого разработчика снимками базы данных с возможностью перезаписи, которые он использует в разработке. Обновление при этом происходит ежедневно в виде конвейера, который включает формирование LVM-снимков данных производственной среды, анонимизацию этого датасета путем удаления всей личной информации и его последующую передачу через rsync на серверы базы данных разработки. Серверы, в свою очередь, предоставляют ZFS-снимок каждому разработчику вместе с инструментами, позволяющими выполнять переход на новые снимки или делать откат к старым.

Для предоставления данных MariaDB и MongoDB с общими размерами датасетов в 600ГБ и 200ГБ соответственно, мы используем такой же конвейер, а для Elasticsearch несколько иной его вариант. Несмотря на то, что данные на дисках существенно изменяются для всех источников, rsync все равно экономит немало времени, каждую ночь передавая приблизительно 1/3 всего датасета.

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

К таким моментам можно отнести проблему, которая в итоге привела к раскрытию поистине старого бага ядра Linux, связанного, в частности, с реализацией TCP. Дело в том, что передача rsync от исходного сервера по неочевидным причинам начала постоянно зависать, хотя в остальном все работало в штатном режиме. Более того, как в итоге выяснилось, эту проблему невозможно было воссоздать намеренно, хотя некоторые действия (например, добавление ограничения скорости на уровне rsync) снижали частоту ее появления, диапазон которой составлял от 1-2 раз в неделю до 1 раза в три месяца.

Поначалу мы не придали этой проблеме должного внимания из-за наличия более актуальных и важных задач, пометив ее как «состояние гонки в rsync», которым как-нибудь нужно заняться, и использовали уже описанный обходной путь с ограничением скорости передачи.

Но в итоге она начала возникать буквально ежедневно.

rsync как конвейер

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

1. rsync запускается как один процесс на клиенте и один процесс на сервере, взаимодействующие через пару сокетов. При использовании же демона rsync, как в нашем случае, коммуникация выполняется через простое TCP-соединение.
2. В зависимости от направления синхронизации после завершения начального рукопожатия каждая конечная точка получает роль отправителя либо получателя. В нашем случае клиент выступает как получатель, а сервер как отправитель.
3. Получатель создает ветку дополнительного процесса, называемого генератор, который использует тот же сокет, что и процесс получателя. Генератор определяет, что ему нужно запросить у отправителя, после чего отправитель посылает эти данные получателю. В итоге после этого шага мы, по сути, получаем конвейер: генератор -> отправитель -> получатель, где стрелки отражают два направления одного TCP-соединения. Несмотря на то, что в процессе присутствует система уведомлений, конвейер оперирует с использованием блокировки и для контроля обратного потока опирается на буферы ОС и окна получения TCP.

«Призрак» в сети?

Когда мы только столкнулись с проблемой, то первым делом предположили наличие в сети ошибок, что было вполне логичным, так как незадолго до этого был произведен апгрейд серверов и свитчей. Исключив всех стандартных подозреваемых (баги прошивки NIC, связанные с разгрузкой TSO/GSO/GRO/VLAN, чрезмерным отбрасыванием пакетов или CRC-ошибками свитчей и т.д.), мы пришли к заключению, что здесь все в порядке, и проблема кроется в чем-то другом.

Присоединение зависших процессов при помощи strace и gdb оказалось не особо информативным: генератор подвисал на send(), а отправитель и получатель на recv(), но при этом никакие данные не перемещались. Тем не менее при рассмотрении ядра обоих систем мы обнаружили кое-что интересное. Клиентский сокет rsync, совместно используемый процессами генератора и получателя, находился в следующем состоянии:

$ ss -mito dst :873
State      Recv-Q Send-Q                  Local Address:Port                                 Peer Address:Port
ESTAB      0      392827 ?             2001:db8:2a::3:38022                             2001:db8:2a::18:rsync                 timer:(persist,1min56sec,0)
	 skmem:(r0,rb4194304,t0,tb530944,f3733,w401771,o0,bl0,d757) ts sack cubic wscale:7,7 rto:204 backoff:15 rtt:2.06/0.541 ato:40 mss:1428 cwnd:10 ssthresh:46 bytes_acked:22924107 bytes_received:100439119971 segs_out:7191833 segs_in:70503044 data_segs_out:16161 data_segs_in:70502223 send 55.5Mbps lastsnd:16281856 lastrcv:14261988 lastack:3164 pacing_rate 133.1Mbps retrans:0/11 rcv_rtt:20 rcv_space:2107888 notsent:392827 minrtt:0.189

На сервере же состояние сокета было таким:

$ ss -mito src :873
State      Recv-Q Send-Q                Local Address:Port                                 Peer Address:Port
ESTAB      0      0                   2001:db8:2a::18:rsync                              2001:db8:2a::3:38022                 timer:(keepalive,3min7sec,0)
 	 skmem:(r0,rb3540548,t0,tb4194304,f0,w0,o0,bl0,d292) ts sack cubic wscale:7,7 rto:204 rtt:1.234/1.809 ato:40 mss:1428 cwnd:1453 ssthresh:1431 bytes_acked:100439119971 bytes_received:22924106 segs_out:70503089 segs_in:7191833 data_segs_out:70502269 data_segs_in:16161 send 13451.4Mbps lastsnd:14277708 lastrcv:16297572 lastack:7012576 pacing_rate 16140.1Mbps retrans:0/794 rcv_rtt:7.5 rcv_space:589824 minrtt:0.026

Интересно то, что на клиенте генератор запрашивает с сервера отправку 3.5Мб данных (1 в первом выводе). Однако в то время как Recv-Q сервера пуст, и он способен принимать данные, ничего не передается. Если бы Recv-Q во втором выводе не равнялся нулю, то мы бы наблюдали зависание rsync на сервере и его невозможность считывать из сети данные. Тем не менее здесь мы видим, что rsync получил все входящие данные, и его вины тут нет.

Так почему же данные на одном конце соединения выстраиваются в очередь, когда второй конец вполне может их принять? Ответ незатейливо кроется в полях timer обоих выводов ss, в частности в timer:(persist,1min56sec,0). Цитируем ss(8):

-o, --options
              Show timer information. For TCP protocol, the output format is:

              timer:(<timer_name>,<expire_time>,<retrans>)

              <timer_name>
                     the name of the timer, there are five kind of timer names:

                     on : means one of these  timers:  TCP  retrans  timer,  TCP
                     early retrans timer and tail loss probe timer

                     keepalive: tcp keep alive timer

                     timewait: timewait stage timer

                     persist: zero window probe timer

                     unknown: none of the above timers

persist означает, что соединение получило уведомление о нулевом окне и ожидает от пира уведомления о ненулевом.

Нулевые окна TCP и зонды нулевых окон

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

Когда буфер получения (Recv-Q) одной стороны заполняется (в данном случае, потому что процесс rsync выполняет на диске операции ввода/вывода со скоростью меньшей, чем скорость сети), эта сторона отправляет сигнал нулевого окна, который приостанавливает передачу по данному направлению. Когда в конечном итоге буфер освобождается, ядро отправляет незапрашиваемое уведомление с ненулевым окном, и передача данных возобновляется. Для верности на случай потери этого уведомления встречная сторона регулярно опрашивает состояние соединения, используя так называемые зонды нулевого окна (Zero Window Probes), режим persist, который мы здесь и наблюдаем.

Окно «заело» в закрытом состоянии

Настало время копнуть поглубже и использовать tcpdump для оценки происходящего на уровне сети:

 […]
09:34:34.165148 0c:c4:7a:f9:68:e4 > 0c:c4:7a:f9:69:78, ethertype IPv6 (0x86dd), length 86: (flowlabel 0xcbf6f, hlim 64, next-header TCP (6) payload length: 32) 2001:db8:2a::3.38022 > 2001:db8:2a::18.873: Flags [.], cksum 0x711b (incorrect -> 0x4d39), seq 4212361595, ack 1253278418, win 16384, options [nop,nop,TS val 2864739840 ecr 2885730760], length 0
09:34:34.165354 0c:c4:7a:f9:69:78 > 0c:c4:7a:f9:68:e4, ethertype IPv6 (0x86dd), length 86: (flowlabel 0x25712, hlim 64, next-header TCP (6) payload length: 32) 2001:db8:2a::18.873 > 2001:db8:2a::3.38022: Flags [.], cksum 0x1914 (correct), seq 1253278418, ack 4212361596, win 13831, options [nop,nop,TS val 2885760967 ecr 2863021624], length 0
[… repeats every 2 mins]

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

? В действительности умноженное на 128, так как фактор масштабирования окна равен 7.

Мы, наконец, сдвинулись с мертвой точки, и теперь есть над чем работать. В какой-то момент клиент столкнулся с объявлением сервера о нулевом окне, как частью стандартного управления потоком TCP, но затем по непонятной причине окно не открылось повторно. Клиент по-прежнему игнорирует объявляемые сервером обновления окна, поэтому передача стоит.

Обработка TCP-ввода в Linux

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

Обработка TCP-пакетов происходит в net/ipv4/tcp_input.c. Несмотря на то, что в пути прописан компонент ipv4, этот код по большей части общий для IPv4 и IPv6.

После некоторых поисков мы выяснили, что входящие обновления окна обрабатываются в tcp_ack_update_window, а фактическое обновление контролируется следующей функцией:

/* Проверка доступности обновления окна.
 * Функция предполагает, что snd_una<=ack<=snd_next.
 */
static inline bool tcp_may_update_window(const struct tcp_sock *tp,
					const u32 ack, const u32 ack_seq,
					const u32 nwin)
{
	return	after(ack, tp->snd_una) || ?
		after(ack_seq, tp->snd_wl1) || ?
		(ack_seq == tp->snd_wl1 && nwin > tp->snd_wnd); ?
}

Переменные ack, ack_seq, snd_wl1 и snd_una содержат порядковые номера TCP для отслеживания переданных данных. Эти номера являются 32-битными беззнаковыми целыми числами (u32) и увеличиваются на 1 при каждом переданном байте, начиная с произвольного стартового значения (начальный порядковый номер). Вот их сводка:

• ack_seq – номер входящего сегмента.
• Ack – номер подтверждения, содержащийся во входящем сегменте. Он подтверждает порядковый номер последнего сегмента, полученного от нас пиром.
• snd_wl1 – номер входящего сегмента, который последним обновил окно получения пира.
• snd_una – номер первого не подтвержденного сегмента, то есть отправленного, но еще не подтвержденного пиром.

Будучи целыми числами фиксированного размера, порядковые номера в конечном итоге будут циклически повторяться, поэтому в условиях такого повторения сравнение двух номеров поручается макросу after().

В качестве справки заметим, что имена snd_una и snd_wl1 взяты непосредственно из первой спецификации TCP в RFC 793(англ.) 1981 года!
Выражая довольно запутанную проверку простым языком, мы хотим получать обновление окна от пира, если он:

? Подтверждает получение отправленных нами данных.

? Отправляет новые данные после предыдущего обновления окна.

? Не отправляет новые данные после обновления окна, но объявляет окно большего размера.

Обратите внимание, что сравнение ack_seq и snd_wl1 гарантирует, что окно не будет обновлено случайно (повторно передаваемым) сегментом, который уже был просмотрен.

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

Доступ к внутреннему состоянию ядра

Для получения доступа к состоянию ядра нужно каким-то образом выполнить внутри него код. Одним из способов было пропатчить ядро несколькими вызовами printk() в нужных местах, но это потребовало бы перезагрузки машины и ожидания очередного зависания rsync. Вместо этого мы решили пропатчить ядро в реальном времени при помощи systemtap(англ.), использовав следующий скрипт:

probe kernel.statement("tcp_ack@./net/ipv4/tcp_input.c:3751")
{
  if ($sk->sk_send_head != NULL) {
	  ack_seq = @cast(&$skb->cb[0], "tcp_skb_cb", "kernel<net/tcp.h>")->seq
	  printf("ack: %d, ack_seq: %d, prior_snd_una: %d\n", $ack, ack_seq, $prior_snd_una)
	  seq = @cast(&$sk->sk_send_head->cb[0], "tcp_skb_cb", "kernel<net/tcp.h>")->seq
	  end_seq = @cast(&$sk->sk_send_head->cb[0], "tcp_skb_cb", "kernel<net/tcp.h>")->end_seq
	  printf("sk_send_head seq:%d, end_seq: %d\n", seq, end_seq)

	  snd_wnd = @cast($sk, "tcp_sock", "kernel<linux/tcp.h>")->snd_wnd
	  snd_wl1 = @cast($sk, "tcp_sock", "kernel<linux/tcp.h>")->snd_wl1
	  ts_recent = @cast($sk, "tcp_sock", "kernel<linux/tcp.h>")->rx_opt->ts_recent
	  rcv_tsval = @cast($sk, "tcp_sock", "kernel<linux/tcp.h>")->rx_opt->rcv_tsval
	  printf("snd_wnd: %d, tcp_wnd_end: %d, snd_wl1: %d\n", snd_wnd, $prior_snd_una + snd_wnd, snd_wl1)
	  printf("flag: %x, may update window: %d\n", $flag, $flag & 0x02)
	  printf("rcv_tsval: %d, ts_recent: %d\n", rcv_tsval, ts_recent)
	  print("\n")
     }
}

Systemtap работает путем преобразования своих скриптов в Си и построения модуля ядра, который патчит его «нагорячую» и переопределяет конкретные инструкции. Здесь мы переопределили системный вызов tcp_ack(), дописали свой код в его конец и сбросили внутреннее состояние TCP-соединения. Проверка $sk->sk_send_head != NULL предоставляет быстрый способ сопоставлять только соединения с ненулевым Send-Q.

Загрузка полученного модуля в ядро привела к следующему:

ack: 4212361596, ack_seq: 1253278418, prior_snd_una: 4212361596
sk_send_head seq:4212361596, end_seq: 4212425472
snd_wnd: 0, tcp_wnd_end: 4212361596, snd_wl1: 1708927328
flag: 4100, may update window: 0
rcv_tsval: 2950255047, ts_recent: 2950255047

Здесь нас интересует два момента: snd_wl1: 1708927328 и ack_seq: 1253278418. Дело не просто в том, что, как и ожидалось, они отличаются, а в том, что ack_seq меньше, чем snd_wl1, то есть отсчет значений ack_seq в определенный момент возобновился с начала, а значение snd_wl1 какое-то время не обновлялось. Воспользовавшись правилами арифметики последовательных чисел(англ.), можно выяснить, что эта конечная точка с момента последнего обновления snd_wl1 получила не менее 3.8ГБ.

Мы уже видели, что поле snd_wl1 содержит последний порядковый номер, использованный для обновления окна получения пира (а значит и нашего окна отправки) и в конечном итоге должно гарантировать защиту от обновления окон на основе старых сегментов. Все должно быть в порядке, если snd_wl1 какое-то время не обновится, но при этом отставание от ack_seq не должно становиться слишком большим, иначе возникает риск отклонения допустимых обновлений окна, как в нашем случае. Поэтому все выглядит так, будто ядро Linux по каким-то причинам не может обновить snd_wl1, что ведет к невозможности выхода из состояния нулевого окна.

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

Обращение к мейнтейнерам

Хорошенько переварив информацию, мы составили обращение к мейнтейнерам ядра Linux , в котором указали все, что удалось на тот момент выяснить, вместе со своими домыслами по этому поводу. Меньше, чем через два часа мы получили ответ вместе с патчем от Нила Кардуэлла.

Оказалось, что баг находился в быстром пути получателя объемных данных, то есть пути кода, который пропускает большую часть строгой дорогостоящей TCP-обработки с целью оптимизации производительности в типичных случаях получения большого объема данных. Это серьезная оптимизация, подчеркнутая еще 28 лет назад² Ваном Якобсоном в его письме “TCP receive in 30 instructions” (TCP-приемник в 30 инструкциях кода). Очевидно, что реализация Linux, находясь в быстром пути получателя, не обновляла snd_wl1. Когда соединение использует быстрый путь слишком долго, snd_wl1 настолько отстает, что ack_seq опережает его «на круг». Если же это происходит при нулевом окне получения, пропадает возможность повторного открытия этого окна, как и было показано выше. Более того, эта ошибка присутствовала в Linux, начиная с версии 2.1.8, которая датируется аж 1996 годом!

? Данная оптимизация актуальна и по сей день: относительно недавняя попытка упростить код, удалив из него прогнозирование заголовков и связанные с ними быстрые пути, потерпела неудачу по причине снижения производительности.

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

После недолгого обсуждения итоговый коммит был размещен в linux-net, откуда перетек в основную линию Linux для 5.10-rc1. В конечном итоге он был внедрен в стабильные серии ядер 4.9 и 4.19, которые мы используем на наших системах Debian с версиями 4.9.241 и 4.19.153, соответственно.

Послесловие

Несмотря на то, что баг был исправлен, нас по-прежнему интересовала пара вопросов, а именно:

1. Как возможно, что TCP-ошибка, которая ведет к зависанию соединений, оставалась незамеченной на протяжении 24 лет?
2. Как получилось, что, работая с инфраструктурой из более 600 систем, выполняющих всевозможные виды ПО, мы заметили этот баг только при использовании rsync?

На эти вопросы сложно ответить определенно, но можно порассуждать:

1. Эта ошибка не будет вызываться большинством протоколов L7. В «синхронных» протоколах запрос-ответ, например в HTTP, обычно каждая сторона будет потреблять все доступные данные перед отправкой. В таком случае, даже если snd_wl1 сделает круг, получатель объемных данных сохранит ненулевое окно и сможет отправить данные, в следствии чего очередное подтверждение обновит это окно и подстроит snd_wl1 через проверку ? в tcp_may_update_window. С другой стороны, rsync использует агрессивный конвейер, в котором сервер может отправлять многогигабайтные ответы, не получая в ходе этого процесса входящие данные. И даже использование rsync через SSH (достаточно распространенная комбинация), а не через простой TCP-транспорт, не выявляло эту неполадку, поскольку фрейминг/оповещение в SSH не позволял данным выстраиваться на сервере в очередь подобным образом.
2. Независимо от протокола приложения, получатель должен сохранять нулевое окно в последнем пути достаточно долго (хотя бы на протяжении 2ГБ) для циклического обращения, но не настолько долго, чтобы ack_seq успел снова обогнать snd_wl1. Такой вариант возможен только если не будут утрачены пакеты, и не возникнут другие условия, способные вызвать провал прогнозирования заголовка быстрого пути. На практике же такое очень маловероятно, поскольку TCP сам определяет пропускную способность сети, фактически вызывая утрату пакетов.
3. Большинство приложений будут обрабатывать сетевые таймауты и либо давать сбой, либо переподключаться, что будет похоже на «случайный глюк сети», не оставляющий следов для отладки.

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

Если эта тема вам интересна, и вы относитесь к любителям поохотиться на странные баги, а также поразбираться в коде ядра, напишите нам – мы постоянно ищем талантливых SRE и DevOps-инженеров!