Захватывающий детективный рассказ о поиске и исправлении трудноуловимого и при этом весьма странного бага, который неведомым образом ускользал от обнаружения на протяжении долгих лет взросления системы 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 поможет вам понять последующий анализ. На сайте приводится подробное описание внутренней архитектуры этой программы, так что я просто обобщу наиболее важные пункты:
rsyncзапускается как один процесс на клиенте и один процесс на сервере, взаимодействующие через пару сокетов. При использовании же демонаrsync, как в нашем случае, коммуникация выполняется через простое TCP-соединение.- В зависимости от направления синхронизации после завершения начального рукопожатия каждая конечная точка получает роль отправителя либо получателя. В нашем случае клиент выступает как получатель, а сервер как отправитель.
- Получатель создает ветку дополнительного процесса, называемого генератор, который использует тот же сокет, что и процесс получателя. Генератор определяет, что ему нужно запросить у отправителя, после чего отправитель посылает эти данные получателю. В итоге после этого шага мы, по сути, получаем конвейер:
генератор -> отправитель -> получатель, где стрелки отражают два направления одного 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 байт1, которое клиент, по всей видимости, игнорирует.
¹ В действительности умноженное на 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: %dn", $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: %dn", 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: %dn", snd_wnd, $prior_snd_una + snd_wnd, snd_wl1)
printf("flag: %x, may update window: %dn", $flag, $flag & 0x02)
printf("rcv_tsval: %d, ts_recent: %dn", 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 лет назад2 Ваном Якобсоном в его письме “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, соответственно.
Послесловие
Несмотря на то, что баг был исправлен, нас по-прежнему интересовала пара вопросов, а именно:
- Как возможно, что TCP-ошибка, которая ведет к зависанию соединений, оставалась незамеченной на протяжении 24 лет?
- Как получилось, что, работая с инфраструктурой из более 600 систем, выполняющих всевозможные виды ПО, мы заметили этот баг только при использовании
rsync?
На эти вопросы сложно ответить определенно, но можно порассуждать:
- Эта ошибка не будет вызываться большинством протоколов L7. В «синхронных» протоколах запрос-ответ, например в HTTP, обычно каждая сторона будет потреблять все доступные данные перед отправкой. В таком случае, даже если
snd_wl1сделает круг, получатель объемных данных сохранит ненулевое окно и сможет отправить данные, в следствии чего очередное подтверждение обновит это окно и подстроитsnd_wl1через проверку ❶ вtcp_may_update_window. С другой стороны,rsyncиспользует агрессивный конвейер, в котором сервер может отправлять многогигабайтные ответы, не получая в ходе этого процесса входящие данные. И даже использованиеrsyncчерез SSH (достаточно распространенная комбинация), а не через простой TCP-транспорт, не выявляло эту неполадку, поскольку фрейминг/оповещение в SSH не позволял данным выстраиваться на сервере в очередь подобным образом. - Независимо от протокола приложения, получатель должен сохранять нулевое окно в последнем пути достаточно долго (хотя бы на протяжении 2ГБ) для циклического обращения, но не настолько долго, чтобы
ack_seqуспел снова обогнатьsnd_wl1. Такой вариант возможен только если не будут утрачены пакеты, и не возникнут другие условия, способные вызвать сбой прогнозирования заголовка быстрого пути. На практике же такое очень маловероятно, поскольку TCP сам определяет пропускную способность сети, фактически вызывая утрату пакетов. - Большинство приложений будут обрабатывать сетевые таймауты и либо давать сбой, либо переподключаться, что будет похоже на «случайный глюк сети», не оставляющий следов для отладки.
Наконец, даже если ничто из вышеперечисленного не происходит, и ваше TCP-соединение регулярно зависает, потребуется немало усилий, чтобы добраться до корней проблемы в коде ядра. Однако этот непростой процесс вознаградит вас увлекательным приключением, в котором вы многое узнаете об истории интернет-протоколов, заглянете в священные недра ядра и пронаблюдаете, как происходит решение подобных проблем в открытых проектах.
Если эта тема вам интересна, и вы относитесь к любителям поохотиться на странные баги, а также поразбираться в коде ядра, напишите нам – мы постоянно ищем талантливых SRE и DevOps-инженеров!
Автор: Дмитрий Брайт
