[Перевод] Фольклор программистов и инженеров (часть 3)
Последняя часть подборки историй из интернета о том, как у багов иногда бывают совершенно невероятные проявления. Первая часть, вторая часть.
Маленький SSH, который (иногда) не мог
Это рассказ об одной из самых увлекательных охот на баг, в которой мне посчастливилось участвовать.
В компании AdGear Technologies Inc., где я работал, королём был SSH. Мы применяли его для управления, мониторинга, развёртывания, сбора журналов, даже для потокового вещания в реальном времени. Этот протокол устойчивый и надёжный, обладает предсказуемостью нативного Unix-инструмента и просто работает.
Но однажды случайные Cron-письма подсказали нам, что протокол не работает.
Таймаут
На машинах в нашем лондонском ЦОДе возникали случайные сбои при отправке файлов журналов в ЦОД в Монреале. Эта задача периодически запускалась из Cron, и сбой проявлялся так:
- Cron-письма сообщали о проблемах с SSH.
- Иногда он зависает.
- Иногда завершается без ошибки по таймауту.
- При внутренней проверке работоспособности Nagios предупреждает об отсутствующих данных в Монреале.
Мы залогинились на лондонские машины, вручную запустили команду push
и она успешно отработала. Мы списали это на временные сетевые неполадки.
Таймауты
Но сбои продолжали случайным образом повторяться. Раз в день, пару раз в день, утром в пятницу, несколько раз в час. Было понятно, что становится хуже. Мы продолжали вручную пушить файлы, пока не поняли, в чём заключается проблема.
Между Лондоном и Монреалем было 17 хопов. Мы создали профиль задержек и потерь пакетов. Оказалось, что на паре хопов терялось 1–3% пакетов. Вместе с отделом эксплуатации лондонского ЦОДа мы заявку на перемаршрутизацию.
Пока лондонцы проверяли информацию о потере пакетов, мы начали искать случайные таймауты на пути от Лондона до нашего второго ЦОДа в Монреале. Хопы на этом маршруте были другие, не те, на которых терялись пакеты. Мы решили, что потеря — не главная проблема, к тому же лондонцы сообщили, что не могут воспроизвести потерю пакетов или таймауты, и что на их стороне всё выглядит нормально.
Апокалипсис
Пересылая вручную сбойные Cron-письма, мы заметили интересную закономерность. Файлы либо успешно передавались на большой скорости, либо вообще не передавались и зависали по таймауту. Не было случаев, чтобы файлы успешно загружались на низкой скорости.
Убрав из уравнения большую часть данных, мы смогли воссоздать сценарий с помощью простого ванильного SSH. В лондонском ЦОДе сервер «SSH mtl-machine» либо моментально выполнял задачу, либо повисал и не мог установить соединение. Удивление начало расти.
Куда делись пакеты?
Мы трижды проверили конфигурацию SSH-севера и работу систем в Монреале:
- DNS-серверы отвечали быстро.
- Зона обратного просмотра DNS была отключена.
- Максимальное количество клиентских подключений было достаточно велико.
- Нас не атаковали.
- Канал не был забит.
Кроме того, даже если что-то не работало, мы наблюдали бы зависания при работе с двумя разными ЦОДами в Монреале. Причём наши нелондонские ЦОДы успешно общались с Монреалем. То есть проблема была связана с Лондоном.
Мы запустили tcpdump и стали наблюдать за пакетами. Нас интересовала общая динамика и данные, полученные с помощью Pcaps и загруженные в Wireshark. Мы увидели признаки потери пакетов и повторной отправки, но всё было на минимальном уровне и вызывало беспокойства.
Затем мы целиком проанализировали подключения в ситуациях, когда связь по SSH устанавливалась успешно, а затем — подключения в ситуациях, когда связь по SSH зависала.
Когда подключение из Лондона к Монреалю зависло, мы пришли к таким выводам:
- Установка связи по TCP прошла нормально.
- Туда-обратно была передана служебная SSH-информация. Где нужно, были нормальные TCP ack-пакеты.
- Определённый пакет был отправлен из Лондона и получен в Монреале.
- Тот же пакет был несколько раз заново отправлен из Лондона и получен в Монреале.
- Просто Монреаль на это не отвечает!
Было непонятно, почему не отвечает Монреаль (из-за этого Лондон отправляет данные заново). На этом соединение зависло, потому что завис протокол 4 уровня. Ещё более волнительным было то, что если в Лондоне прервать повторную SSH-отправку и сразу же её перезапустить, то она успешно отработает. В этом случае tcpdump показывал, что Монреаль получил пакет и ответил на это, и работа продолжалась.
На SSH-клиенте в Лондоне мы включили подробную отладку (-vvv
), и после этих записей в журнале связь повисла:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: mac_setup: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_setup: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
Мы погуглили по запросу «SSH hang SSH2_MSG_KEX_DH_GEX_GROUP» и получили много результатов: от проблем с Wi-Fi до TCP—багов в Windows и глючных маршрутизаторов, теряющих TCP-фрагменты. В качестве одного из решений для LAN предлагалось вычислить MSS пути и задать это значение в качестве MTU на обоих концах маршрута.
Я продолжал уменьшать MTU на лондонском сервере с 1500 — это не помогало до тех пор, пока я не дошёл до волшебного значения 576. После этого зависание SSH больше не повторялось. У меня исполнялся скрипт с SSH-циклом, и по желанию я мог вызвать таймауты, вернув MTU значение 1500, или избавиться от них, задав 576. К сожалению, это публичные рекламные серверы, и глобальное назначение MTU 1500 не решит проблемы. Однако выше уже упоминалось, что, вероятно, где-то сломан процесс фрагментации или пересборки пакетов.
Вернёмся к проверке полученных пакетов с помощью tcpdump: признаков фрагментации не было. Размер полученного пакета полностью соответствовал размеру отправленного. Если что-то фрагментировало пакет на байте 576+, то что-то успешно собирало его обратно.
Мерцай-мерцай, кривая звёздочка
Углубившись в анализ, я изучал полные дампы пакетов (tcpdump -s 0 -X
), а не одни лишь заголовки. При сравнении волшебного пакета из успешной отправки с пакетом из сбойной отправки, я почти не нашёл различий, за исключением TCP/IP-заголовков. Но было очевидно, что это первый пакет в TCP-соединении, содержавший достаточно данных для прохода через отметку в 576 байтов. Все предыдущие пакеты были гораздо меньше.
Сравнив тот же пакет из сбойной отправки, в том виде, в каком он покинул Лондон и пришёл в Монреаль, мой взгляд за что-то зацепился. За что-то малозаметное, и я отмахнулся из-за усталости (был поздний вечер пятницы). Но после нескольких обновлений и сравнений мне уже не мерещилось.
0×0040: 0b7c aecc 1774 b770 ad92 0000 00b7 6563 .|…t.p…ec
0×0050: 6468 2d73 6861 322d 6e69 7374 7032 3536 dh-sha2-nistp256
0×0060: 2c65 6364 682d 7368 6132 2d6e 6973 7470, ecdh-sha2-nistp
0×0070: 3338 342c 6563 6468 2d73 6861 322d 6e69 384, ecdh-sha2-ni
0×0080: 7374 7035 3231 2c64 6966 6669 652d 6865 stp521, diffie-he
0×0090: 6c6c 6d61 6e2d 6772 6f75 702d 6578 6368 llman-group-exch
0×00a0: 616e 6765 2d73 6861 3235 362c 6469 6666 ange-sha256, diff
0×00b0: 6965 2d68 656c 6c6d 616e 2d67 726f 7570 ie-hellman-group
0×00c0: 2d65 7863 6861 6e67 652d 7368 6131 2c64 -exchange-sha1, d
0×00d0: 6966 6669 652d 6865 6c6c 6d61 6e2d 6772 iffie-hellman-gr
0×00e0: 6f75 7031 342d 7368 6131 2c64 6966 6669 oup14-sha1, diffi
0×00f0: 652d 6865 6c6c 6d61 6e2d 6772 6f75 7031 e-hellman-group1
0×0100: 2d73 6861 3100 0000 2373 7368 2d72 7361 -sha1…#SSH-rsa
0×0110: 2c73 7368 2d64 7373 2c65 6364 7361 2d73, SSH-dss, ecdsa-s
0×0120: 6861 322d 6e69 7374 7032 3536 0000 009d ha2-nistp256…
0×0130: 6165 7331 3238 2d63 7472 2c61 6573 3139 aes128-ctr, aes19
0×0140: 322d 6374 722c 6165 7332 3536 2d63 7472 2-ctr, aes256-ctr
0×0150: 2c61 7263 666f 7572 3235 362c 6172 6366, arcfour256, arcf
0×0160: 6f75 7231 3238 2c61 6573 3132 382d 6362 our128, aes128-cb
0×0170: 632c 3364 6573 2d63 6263 2c62 6c6f 7766 c,3des-cbc, blowf
0×0180: 6973 682d 6362 632c 6361 7374 3132 382d ish-cbc, cast128-
0×0190: 6362 632c 6165 7331 3932 2d63 6263 2c61 cbc, aes192-cbc, a
0×01a0: 6573 3235 362d 6362 632c 6172 6366 6f75 es256-cbc, arcfou
0×01b0: 722c 7269 6a6e 6461 656c 2d63 6263 406c r, rijndael-cbc@l
0×01c0: 7973 6174 6f72 2e6c 6975 2e73 6500 0000 ysator.liu.se…
0×01d0: 9d61 6573 3132 382d 6374 722c 6165 7331 .aes128-ctr, aes1
0×01e0: 3932 2d63 7472 2c61 6573 3235 362d 6374 92-ctr, aes256-ct
0×01f0: 722c 6172 6366 6f75 7232 3536 2c61 7263 r, arcfour256, arc
0×0200: 666f 7572 3132 382c 6165 7331 3238 2d63 four128, aes128-c
0×0210: 6263 2c33 6465 732d 6362 632c 626c 6f77 bc,3des-cbc, blow
0×0220: 6669 7368 2d63 6263 2c63 6173 7431 3238 fish-cbc, cast128
0×0230: 2d63 6263 2c61 6573 3139 322d 6362 632c -cbc, aes192-cbc,
0×0240: 6165 7332 3536 2d63 6263 2c61 7263 666f aes256-cbc, arcfo
0×0250: 7572 2c72 696a 6e64 6165 6c2d 6362 6340 ur, rijndael-cbc@
0×0260: 6c79 7361 746f 722e 6c69 752e 7365 0000 lysator.liu.se…
0×0270: 00a7 686d 6163 2d6d 6435 2c68 6d61 632d …hmac-md5, hmac-
0×0280: 7368 6131 2c75 6d61 632d 3634 406f 7065 sha1, umac-64@ope
0×0290: 6e73 7368 2e63 6f6d 2c68 6d61 632d 7368 nSSH.com, hmac-sh
0×02a0: 6132 2d32 3536 2c68 6d61 632d 7368 6132 a2–256, hmac-sha2
0×02b0: 2d32 3536 2d39 362c 686d 6163 2d73 6861 -256–96, hmac-sha
0×02c0: 322d 3531 322c 686d 6163 2d73 6861 322d 2–512, hmac-sha2-
0×02d0: 3531 322d 3936 2c68 6d61 632d 7269 7065 512–96, hmac-ripe
0×02e0: 6d64 3136 302c 686d 6163 2d72 6970 656d md160, hmac-ripem
0×02f0: 6431 3630 406f 7065 6e73 7368 2e63 6f6d d160@openSSH.com
0×0300: 2c68 6d61 632d 7368 6131 2d39 362c 686d, hmac-sha1–96, hm
0×0310: 6163 2d6d 6435 2d39 3600 0000 a768 6d61 ac-md5–96…hma
0×0320: 632d 6d64 352c 686d 6163 2d73 6861 312c c-md5, hmac-sha1,
0×0330: 756d 6163 2d36 3440 6f70 656e 7373 682e umac-64@openSSH.
0×0340: 636f 6d2c 686d 6163 2d73 6861 322d 3235 com, hmac-sha2–25
0×0350: 362c 686d 6163 2d73 6861 322d 3235 362d 6, hmac-sha2–256-
0×0360: 3936 2c68 6d61 632d 7368 6132 2d35 3132 96, hmac-sha2–512
0×0370: 2c68 6d61 632d 7368 6132 2d35 3132 2d39, hmac-sha2–512–9
0×0380: 362c 686d 6163 2d72 6970 656d 6431 3630 6, hmac-ripemd160
0×0390: 2c68 6d61 632d 7269 7065 6d64 3136 3040, hmac-ripemd160@
0×03a0: 6f70 656e 7373 682e 636f 6d2c 686d 6163 openSSH.com, hmac
0×03b0: 2d73 6861 312d 3936 2c68 6d61 632d 6d64 -sha1–96, hmac-md
0×03c0: 352d 3936 0000 0015 6e6f 6e65 2c7a 6c69 5–96…none, zli
0×03d0: 6240 6f70 656e 7373 682e 636f 6d00 0000 b@openSSH.com…
0×03e0: 156e 6f6e 652c 7a6c 6962 406f 7065 6e73 .none, zlib@opens
0×03f0: 7368 2e63 6f6d 0000 0000 0000 0000 0000 sh.com…
0×0400: 0000 0000 0000 0000 0000 0000…
0×0040: 0b7c aecc 1774 b770 ad92 0000 00b7 6563 .|…t.p…ec
0×0050: 6468 2d73 6861 322d 6e69 7374 7032 3536 dh-sha2-nistp256
0×0060: 2c65 6364 682d 7368 6132 2d6e 6973 7470, ecdh-sha2-nistp
0×0070: 3338 342c 6563 6468 2d73 6861 322d 6e69 384, ecdh-sha2-ni
0×0080: 7374 7035 3231 2c64 6966 6669 652d 6865 stp521, diffie-he
0×0090: 6c6c 6d61 6e2d 6772 6f75 702d 6578 6368 llman-group-exch
0×00a0: 616e 6765 2d73 6861 3235 362c 6469 6666 ange-sha256, diff
0×00b0: 6965 2d68 656c 6c6d 616e 2d67 726f 7570 ie-hellman-group
0×00c0: 2d65 7863 6861 6e67 652d 7368 6131 2c64 -exchange-sha1, d
0×00d0: 6966 6669 652d 6865 6c6c 6d61 6e2d 6772 iffie-hellman-gr
0×00e0: 6f75 7031 342d 7368 6131 2c64 6966 6669 oup14-sha1, diffi
0×00f0: 652d 6865 6c6c 6d61 6e2d 6772 6f75 7031 e-hellman-group1
0×0100: 2d73 6861 3100 0000 2373 7368 2d72 7361 -sha1…#SSH-rsa
0×0110: 2c73 7368 2d64 7373 2c65 6364 7361 2d73, SSH-dss, ecdsa-s
0×0120: 6861 322d 6e69 7374 7032 3536 0000 009d ha2-nistp256…
0×0130: 6165 7331 3238 2d63 7472 2c61 6573 3139 aes128-ctr, aes19
0×0140: 322d 6374 722c 6165 7332 3536 2d63 7472 2-ctr, aes256-ctr
0×0150: 2c61 7263 666f 7572 3235 362c 6172 6366, arcfour256, arcf
0×0160: 6f75 7231 3238 2c61 6573 3132 382d 6362 our128, aes128-cb
0×0170: 632c 3364 6573 2d63 6263 2c62 6c6f 7766 c,3des-cbc, blowf
0×0180: 6973 682d 6362 632c 6361 7374 3132 382d ish-cbc, cast128-
0×0190: 6362 632c 6165 7331 3932 2d63 6263 2c61 cbc, aes192-cbc, a
0×01a0: 6573 3235 362d 6362 632c 6172 6366 6f75 es256-cbc, arcfou
0×01b0: 722c 7269 6a6e 6461 656c 2d63 6263 406c r, rijndael-cbc@l
0×01c0: 7973 6174 6f72 2e6c 6975 2e73 6500 0000 ysator.liu.se…
0×01d0: 9d61 6573 3132 382d 6374 722c 6165 7331 .aes128-ctr, aes1
0×01e0: 3932 2d63 7472 2c61 6573 3235 362d 6374 92-ctr, aes256-ct
0×01f0: 722c 6172 6366 6f75 7232 3536 2c61 7263 r, arcfour256, arc
0×0200: 666f 7572 3132 382c 6165 7331 3238 2d63 four128, aes128-c
0×0210: 6263 2c33 6465 732d 6362 632c 626c 6f77 bc,3des-cbc, blow
0×0220: 6669 7368 2d63 6263 2c63 6173 7431 3238 fish-cbc, cast128
0×0230: 2d63 6263 2c61 6573 3139 322d 6362 632c -cbc, aes192-cbc,
0×0240: 6165 7332 3536 2d63 6263 2c61 7263 666f aes256-cbc, arcfo
0×0250: 7572 2c72 696a 6e64 6165 6c2d 6362 7340 ur, rijndael-cbs@
0×0260: 6c79 7361 746f 722e 6c69 752e 7365 1000 lysator.liu.se…
0×0270: 00a7 686d 6163 2d6d 6435 2c68 6d61 732d …hmac-md5, hmas-
0×0280: 7368 6131 2c75 6d61 632d 3634 406f 7065 sha1, umac-64@ope
0×0290: 6e73 7368 2e63 6f6d 2c68 6d61 632d 7368 nSSH.com, hmac-sh
0×02a0: 6132 2d32 3536 2c68 6d61 632d 7368 7132 a2–256, hmac-shq2
0×02b0: 2d32 3536 2d39 362c 686d 6163 2d73 7861 -256–96, hmac-sxa
0×02c0: 322d 3531 322c 686d 6163 2d73 6861 322d 2–512, hmac-sha2-
0×02d0: 3531 322d 3936 2c68 6d61 632d 7269 7065 512–96, hmac-ripe
0×02e0: 6d64 3136 302c 686d 6163 2d72 6970 756d md160, hmac-ripum
0×02f0: 6431 3630 406f 7065 6e73 7368 2e63 7f6d d160@openSSH.c.m
0×0300: 2c68 6d61 632d 7368 6131 2d39 362c 786d, hmac-sha1–96, xm
0×0310: 6163 2d6d 6435 2d39 3600 0000 a768 7d61 ac-md5–96…h}a
0×0320: 632d 6d64 352c 686d 6163 2d73 6861 312c c-md5, hmac-sha1,
0×0330: 756d 6163 2d36 3440 6f70 656e 7373 782e umac-64@openssx.
0×0340: 636f 6d2c 686d 6163 2d73 6861 322d 3235 com, hmac-sha2–25
0×0350: 362c 686d 6163 2d73 6861 322d 3235 362d 6, hmac-sha2–256-
0×0360: 3936 2c68 6d61 632d 7368 6132 2d35 3132 96, hmac-sha2–512
0×0370: 2c68 6d61 632d 7368 6132 2d35 3132 3d39, hmac-sha2–512=9
0×0380: 362c 686d 6163 2d72 6970 656d 6431 3630 6, hmac-ripemd160
0×0390: 2c68 6d61 632d 7269 7065 6d64 3136 3040, hmac-ripemd160@
0×03a0: 6f70 656e 7373 682e 636f 6d2c 686d 7163 openSSH.com, hmqc
0×03b0: 2d73 6861 312d 3936 2c68 6d61 632d 7d64 -sha1–96, hmac-}d
0×03c0: 352d 3936 0000 0015 6e6f 6e65 2c7a 7c69 5–96…none, z|i
0×03d0: 6240 6f70 656e 7373 682e 636f 6d00 0000 b@openSSH.com…
0×03e0: 156e 6f6e 652c 7a6c 6962 406f 7065 6e73 .none, zlib@opens
0×03f0: 7368 2e63 6f6d 0000 0000 0000 0000 0000 sh.com…
0×0400: 0000 0000 0000 0000 0000 0000…
Что-нибудь заметили? Если нет, то ничего страшного. Можете скопировать в два окна в текстовом редакторе и быстро переключаться между ними, чтобы увидеть изменения символов.
Так-так. Это не потеря пакетов, а их повреждение! Очень небольшое, очень предсказуемое повреждение. Интересные наблюдения:
- Начальная часть пакета (<576 байтов) не повреждена.
- Повреждён каждый 15-й байт из 16.
- Повреждение предсказуемое. Все
h
сталиx
, всеc
сталиs
.
Вы могли уже свериться с ASCII-таблицей и прийти к выводу: один бит застрял на значении 1
. Превращение в 1
четвёртого бита в байте портит предыдущие буквы слева до значений справа.
Очевидные виновники в нашем поле зрения (NIC-карты, принимающие серверы) вне подозрений, потому что у сбоя есть закономерность (несколько лондонских машин → несколько монреальских ЦОДов и машин). Причина должна быть на маршруте и ближе к Лондону.
Ситуация начала обретать смысл. Я также заметил маленькую подсказку в подробном режиме tcpdump (tcp cksum bad
), которую раньше не замечал. Монреальский сервер отбрасывал пакет на уровне ядра, когда понимал, что тот повреждён, и не передавал пакет SSH-демону в пользовательском пространстве. Затем Лондон снова отправлял пакет, тот опять повреждался, а Монреаль молча его отбрасывал. С точки зрения SSH и SSHd, соединение зависло. С точки зрения tcpdump, потерь не было, а монреальские серверы просто игнорируют данные.
Мы сообщили о своих находках в отдел эксплуатации лондонского ЦОДа, и через несколько минут они сильно изменили исходящие маршруты. Первый хоп и большинство последующих были другими. Проблема зависания исчезла.
Фиксы поздней ночью в пятницу приятны, потому что на выходных можно расслабиться и не думать о проблемах и службе поддержки :)
Где Вальдо?
Радуясь, что мы больше не страдаем от этой проблемы и что наши системы навёрстывают отставание, я решил найти устройство, виновное в этом повреждении пакетов.
Обновление лондонских маршрутов, чтобы трафик не шёл по старому пути, означало, что я не смогу легко воспроизвести проблему. Я нашёл в Монреале друга с подходящей машиной под FreeBSD, которая была доступна из Лондона по старым маршрутам.
Я хотел убедиться в предсказуемости повреждения даже без участия SSH. Мне это легко удалось с помощью нескольких конвейеров.
В Монреале:
nc -l -p 4000 > /dev/null
Затем в Лондоне:
cat /dev/zero | nc mtl 4000
Учитывая фактор случайности и настройку в цикле повторных попыток, я получил несколько пакетов, которые развеяли все сомнения относительно предыдущих умозаключений. Вот часть одного из пакетов:
0×0210…
0×0220 0000 0000 0000 0000 0000 0000 0000 0000…
0×0230 0000 0000 0000 0000 0000 0000 0000 0000…
0×0240 0000 0000 0000 0000 0000 0000 0000 0000…
0×0250 0000 0000 0000 0000 0000 0000 0000 1000…
0×0260 0000 0000 0000 0000 0000 0000 0000 1000…
0×0270 0000 0000 0000 0000 0000 0000 0000 1000…
0×0280 0000 0000 0000 0000 0000 0000 0000 1000…
0×0290 0000 0000 0000 0000 0000 0000 0000 1000…
0×02a0 0000 0000 0000 0000 0000 0000 0000 1000…
0×02b0 0000 0000 0000 0000 0000 0000 0000 1000…
0×02c0 0000 0000 0000 0000 0000 0000 0000 1000…
0×02d0 0000 0000 0000 0000 0000 0000 0000 1000…
0×02e0 0000 0000 0000 0000 0000 0000 0000 1000…
0×02f0 0000 0000 0000 0000 0000 0000 0000 1000…
0×0300 0000 0000 0000 0000 0000 0000 0000 1000…
0×0310 0000 0000 0000 0000 0000 0000 0000 1000…
0×0320 0000 0000 0000 0000 0000 0000 0000 1000…
0×0330 0000 0000 0000 0000 0000 0000 0000 1000…
0×0340 0000 0000 0000 0000 0000 0000 0000 1000…
0×0350 0000 0000 0000 0000 0000 0000 0000 1000…
0×0360 0000 0000 0000 0000 0000 0000 0000 1000…
0×0370 0000 0000 0000 0000 0000 0000 0000 1000…
0×0380 0000 0000 0000 0000 0000 0000 0000 1000…
0×0390 0000 0000 0000 0000 0000 0000 0000 1000…
0×03a0 0000 0000 0000 0000 0000 0000 0000 1000…
0×03b0 0000 0000 0000 0000 0000 0000 0000 1000…
0×03c0 0000 0000 0000 0000 0000 0000 0000 1000…
0×03d0 0000 0000 0000 0000 0000 0000 0000 0000…
0×03e0…
Воспроизведя баг, мне нужно было найти тот из 17 хопов, на котором возникало повреждение. Я не мог просто позвонить провайдерам всех кластеров и попросить проверить их системы.
Я решил последовательно пропинговать каждый роутер, вдруг это поможет. Написал специальные ICMP-пакеты, достаточно большие, чтобы превысить безопасный рубеж в 576 байтов, и заполнил их нулями. Затем с помощью этих пакетов пропинговал из Лондона монреальский сервер.
Пакеты вернулись неповреждёнными.
Я перепробовал все сочетания скорости, содержимого, размера — безрезультатно. Я не находил повреждений в вернувшихся пинговых ICMP-пакетах.
В netcat-конвейерах я заменил TCP на UDP. Опять никаких повреждений.
Для воспроизведения повреждений нужен был TCP, а для TCP нужны две взаимодействующие конечные точки. Я тщетно пытался выяснить, у всех ли маршрутизаторов есть открытый TCP-порт, с которым я могу взаимодействовать напрямую.
Казалось, нельзя было выявить со стороны сбойный хоп. Или можно?
Mirror mirror on the wall
Чтобы определить, возникает ли повреждение, нужно было воспользоваться одним из сценариев:
- Через TCP-узел, с которым идёт взаимодействие, проверить пакет в пункте назначения.
- Не в пользовательском пространстве, куда пакет не будет доставлен в случае ошибки при проверке контрольной суммы, а проверить полученный пакет на повреждения с помощью root и tcpdump.
- С помощью TCP-узла, который работает как echo-сервер и зеркалирует обратно полученные данные, проверить пакет на отправляющей ноде.
Неожиданно выяснилось, что нам доступна вторая точка замера. Доступна не напрямую, но всё же: при самом первом подходе к решению проблемы мы заметили, что SSH-клиенты виснут, когда общаются с SSH-серверами через повреждающий хоп. Это хороший пассивный сигнал, который можно использовать вместо активного «echo»-сигнала.
И в этом нам могут помочь многочисленные открытые SSH-серверы в интернете.
Нам не нужны актуальные аккаунты на этих серверах, нужно лишь запустить SSH-соединение, посмотреть, будет ли успешной фаза обмена шифрами (при разумном количестве повторных попыток, чтобы учесть случайность повреждения).
План был такой:
- Использовать замечательный инструмент nmap в режиме «random IP» для составления списка географически распределённых открытых SSH-серверов.
- Протестировать каждый сервер и выяснить:
- Если он не отвечает, непредсказуем или использует файрвол → игнорировать его.
- Если успешно общается после N-попыток → пометить «хорошим».
- Если общается с зависаниями в фазе telltale после N-попыток → пометить «плохим».
- Запомнить трассировку для «хороших» и «плохих».
Я думал так: в трассировках всех «плохих» серверов будут использоваться несколько одинаковых хопов. Мы сможем выделить подозрительные хопы и определить те из них, которые используются в трассировках «хороших» серверов. В надежде, что останется один или два.
Потратив час на классификацию серверов вручную, я прекратил исследовать данные. У меня было 16 «плохих» и 25 «хороших» серверов.
Сначала нужно было составить список хопов, которые встречаются во всех трассировках «плохих» серверов. Почистив список, я понял, что мне даже не нужно переходить к списку «хороших», чтобы убрать ложноположительные хопы. У «плохих» был только один общий хоп.
Теме не менее, до него было два провайдера: Лондон → N хопов upstream1 → Y хопов upstream2.
Это был первый из Y хопов в upstream2, прямо на границе между upstream1 и upstream2. Он повреждал случайные TCP-пакеты, что приводило к многочисленным повторным отправкам и, в зависимости от особенностей обмена данными протокола, к зависаниям или снижению объёмов передачи.
Вместе с отделом эксплуатации лондонского ЦОДа мы отследили IP-адрес этого хопа. Я надеялся, что благодаря их прямой связи с upstream1 получится заставить внести исправления.
Через upstream1 я получил подтверждение, что на указанном мной хопе (первом в upstream2) был внутренний «сбой управляющего модуля», который влиял на BGP и маршрутизацию между двумя внутренними сетями. Они перестроили маршрут в обход сбойного устройства и отключили его в ожидании замены.
Фильтр рок-музыки
Я помогал пользователю потокового аудиоприложения настроить работу по локальной сети. У пользователя проигрывалась только классическая музыка, но не роковая. Серьёзно. Классика передавалась без проблем, а при попытке потоковой передачи рок-музыки соединение пропадало через несколько минут.
Приложение получало фрагменты аудио, сжимало их с помощью кодека, сжимающего без потерь, а затем отправляло каждый чанк в отдельном UDP-пакете конечной точке. По мере возможности приложение старалось использовать IPv6, потому что это было надёжнее LAN-окружения, хотя при необходимости могло работать и через IPv4.
После бесконечного и нудного поиска причины проблемы, я наконец-то понял, в чём дело. Каким-то образом пользователь задал в сетевом интерфейсе MTU 1200 байтов. А IPv6 не будет автоматически фрагментировать пакеты на уровне IP при MTU ниже 1280 байтов, так что более крупные пакеты просто не смогут отправиться. Поточное приложение будет пытаться отправить аудиопакеты крупнее 1200 байтов, получать ошибку и разрывать соединение.
Почему такое происходило только с рок-музыкой? Всё просто. Кодеки со сжатием без потерь используют переменный битрейт, а классическая музыка сжимается лучше роковой. При поточной передаче классики звук стабильно сжимался в пакеты менее 1200 байтов, а пакеты с роковой музыкой случайным образом превышали этот порог.
Пользователь не знал, почему уменьшен его MTU, он ему и не был нужен, так что мы увеличили значение и всё стало прекрасно работать.
Самоисчезающий перебой в работе интернета
Поступив в 1999-м в университет, я жил в старом и ветхом студенческом общежитии, потому что не мог позволить себе ничего лучше. Но в общаге хотя бы был довольно приличный интернет, который в моей стране ещё не был широко распространён. А поскольку менять здание запрещалось, сетевые кабели (ещё коаксиальные) были разведены по временной схеме. Их прятали за подвесным потолком в коридорах и протягивали через дверные проёмы в комнаты, где они просто лежали на полу. Любой разрыв связи мог привести к тому, что без сети оставался целый этаж. Поскольку я учился на факультете информатики, то быстро и невольно превратился на своём этаже в человека, который исправляет довольно частые перебои, хотя у меня вообще не было опыта работы с сетями.
Иногда перебой был на стороне провайдера, иногда проблема была связана с нашим прокси, но чаще всего кто-то просто отключал какой-то кабель и не вставлял в него замыкатель.
Однажды вечером пропал интернет, но всего на несколько минут. Затем он снова появился, так что я не придал этому значения. Но на следующий день кратковременный перебой повторился, и на третий день тоже. Обычно он происходил около 20 часов, точное время плавало, а иногда его вообще не было. Но каждый раз, когда сеть пропадала, начинал звонить мой внутриобщажный телефон, а людей всё сильнее раздражали эти повторяющиеся перебои.
Поскольку каждый перебой длился всего несколько минут, я не мог определить конкретное место до того, как сеть снова появлялась. Пробовал пробежать по этажу и стучаться во все двери, спрашивая, не вытащил ли кто-то кабель или не сделал ли с ним что-то, но затея не помогла. Наконец я решил дожидаться ежедневного перебоя со своим верным мультиметром в руке. В течение недели я исключал из подозреваемых одну комнату за другой. Наконец в одном из комнатных кабелей я обнаружил всплеск сопротивления в ходе очередного перебоя.
Я постучал, но мне не открыли. Замок был заперт. Но если в комнате нет никого, кто мог бы что-то сделать с компьютером или кабелем, то почему прерывается соединение? И почему оно восстанавливается? На следующий день всё повторилось, мне снова не открыли на стук в дверь. Я решил совсем отключить эту комнату, чтобы у остального этажа работал интернет.
На следующее утро жильцы той комнаты сообщили мне, что у них не работает интернет. Я пришёл к ним и измерил сопротивление во всех кабелях, проверил все подключения и замыкатели. Во всех кабелях ноль Ом, всё в идеальном порядке. Я спросил парня, что он делал прошлым вечером? Читал учебники перед экзаменами, ничего связанного с компьютером, ответил тот. Я перепроверил всё второй и третий раз, но не нашёл никаких проблем. Я почти сдался, и тут заметил: кабель был закреплён под кроватью. Конечно, медный сердечник кабеля был сломан именно в этом месте, но удерживался оболочкой достаточно плотно, чтобы при нормальных условиях контакт сохранялся, даже если сесть на кровать. Но когда я начал раскачивать её, контакт пропадал на несколько секунд при каждом толчке.
Сами можете предположить, что происходило на той кровати по несколько минут каждый вечер, за запертой дверью и без ответа на стук.
История Мэла
Настоящие программисты пишут на Фортране
Возможно, сейчас это так, в декадентскую эпоху безалкогольного пива, калькуляторов и «user-friendly» приложений, но в Старые Добрые Времена, когда термин «software» звучал забавно, а Настоящие Компьютеры были сделаны из магнитных барабанов и радиоламп, Настоящие Программисты писали на машинном коде. Не на FORTRAN. Не на RATFOR. Даже не на ассемблере. На машинном коде. На настоящих, неприукрашенных, непостижимых шестнадцатеричных числах. Прямо так. Уже несколько поколений программистов выросло, не зная об этом славном прошлом, и я считаю, что должен постараться перекинуть мостик через разрыв поколений и рассказать о том, как Настоящий Программист писал код. Я буду звать его Мэл, потому что так его звали.
Я познакомился с Мэлом, когда устроился в Royal McBee Computer Corp., ныне несуществующую дочернюю компанию производителя печатных машинок. Фирма производила LGP-30 — маленький и дешёвый (по сегодняшним меркам) компьютер на барабанной памяти, — и только что начала производить RPC-4000, тоже на барабанной памяти, намного улучшенный, более крупный и быстрый. Магнитные сердечники стоили слишком дорого, да они и не выдержали конкуренции (поэтому вы не слышали ни об этой компании, ни о её компьютерах). Меня наняли, чтобы я написал FORFTRAN-компилятор для этого нового чуда, а Мэл был моим проводником по его возможностям. Мэл не одобрял компиляторы. «Что хорошего в том, что программа не может переписать собственный код?», — спрашивал он. Мэл написал на шестнадцатеричном коде самую популярную программу компании. Она работала на LGP-30 и играла в блэкджек с потенциальными покупателями на компьютерных выставках. Это всегда оказывало драматический эффект. Стенд с LGP-30 выставлялся на каждой выставке, а продавцы IBM собирались вокруг и беседовали друг с другом. Помогало ли это продавать компьютеры? Этот вопрос мы никогда не обсуждали.
В обязанности Мэла входило переписывание блэкджек-программы под RPC-4000. (Портирование? Что это такое?) У нового компьютера была схема адресации «один-плюс-один»: у каждой машинной инструкции кроме кода операции и адреса нужного операнда был ещё и второй адрес, который показывал, где на вращающемся магнитном барабане записана следующая инструкция. То есть после каждой инструкции шло GO TO
! Набейте это в трубку Pascal и выкурите.
Мэл любил RPC-4000, потому что мог оптимизировать свой код: размещать инструкции на барабане так, чтобы как только одна завершалась, вторая сразу оказывалась под «считывающей головкой» и была готова к немедленному исполнению. Для этого была написана программа, «оптимизирующий ассемблер», но Мэл отказывался ею пользоваться. «Никогда не знаешь, куда она положит данные», — объяснял он, — «поэтому приходится использовать отдельные константы». Я понял суть этой фразы гораздо позже. Поскольку Мэл знал числовые значения всех операционных кодов и присваивал в барабанной памяти собственные адреса, то каждую написанную им инструкцию можно было считать числовой константой. К примеру, он мог выбрать более раннюю инструкцию «сложения» и умножить на неё, если она имела подходящее числовое значение. Его код мало кто мог изменять. Я сравнивал вручную оптимизированные Мэлом программы с тем же кодом, который был обработан оптимизирующим ассемблером, и код Мэла всегда исполнялся быстрее. Дело в том, что метод построения архитектуры «сверху вниз» ещё не изобрели, да Мэл всё равно не пользовался бы им. Сначала он писал внутренние части своих программных циклов, чтобы те первыми получали оптимальные адреса на барабане. А оптимизирующий ассемблер был на такое неспособен. Мэл никогда не писал циклы с задержкой по времени, даже когда неповоротливый Flexowriter требовал делать задержку между выводами символов. Мэл просто размещал инструкции на барабане так, чтобы в момент, когда нужно было считать следующую инструкцию, она проходила мимо считывающей головки, и барабану требовалось сделать ещё один оборот, чтобы её найти. Мэл нашёл для этой процедуры неподражаемый термин. Слово «оптимальный» (optimum) имеет абсолютное значение, как и «уникальный», поэтому в разговорной речи их стали часто делать относительными: «не совсем оптимально», или «менее оптимально», или «не очень оптимально». Мэл называл места на барабане с наибольшим временем задержки «самый пессимум» (pessimum — наихудшие условия среды, переносимые организмом).
Завершив работу над блэкджек-программой и запустив её («Даже инициализатор оптимизирован», — гордо сказал он), Мэл получил от отдела продаж заявку на внесение изменений. За перемешивание карт и сдачи из колоды в программе отвечал элегантный (оптимизированный) генератор случайных чисел. И кто-то из продажников посчитал это слишком честным, потому что иногда покупатели проигрывали. Они попросили Мэла изменить программу так, чтобы с помощью сенсорного включателя на консоли можно было изменить шансы игрока и позволить покупателю выиграть. Мэл отказался. Он считал это нечестным — так оно и было, — и что это посягает на его нравственность программиста — так оно и было, — поэтому отказался в этом участвовать. Мэла уговаривал начальник отдела продаж, и Большой Босс, и коллеги-программисты по настоянию Босса. Наконец Мэл сдался и написал код, но сделал жульническую проверку наоборот: когда включатель был включён, программа жульничала и всегда выигрывала. Мэл был в восторге от своего решения. Он утверждал, что его подсознание проявило неуправляемую этичность и наотрез отказался исправлять программу. Когда Мэл ушёл из компании ради более высокого заработка, Большой Босс попросил меня взглянуть на код и сказать, смогу ли я найти модуль проверки и поменять порядок его работы. Я неохотно согласился.
Разбирательство с кодом Мэла было настоящим приключением. Мне часто казалось, что программирование — это вид искусства, настоящую ценность которого может оценить лишь тот, кто разбирается в этом загадочном искусстве. В нём встречаются настоящие драгоценности и блестящие ходы, самой природой процесса скрытые от человеческого взгляда и восхищения, иногда навсегда. Можно многое узнать о человеке, просто читая его код, даже шестнадцатеричный. Думаю, Мэл был непризнанным гением. Пожалуй, самым сильным потрясением стал найденный мной невинный цикл, в котором не было жульнической проверки. Нет проверки. Нет.
Здравый смысл подсказывал, что это должен быть закрытый цикл, внутри которого циркулирует программа, вечно, бесконечно. Однако программное управление успешно проходило через него и безопасно выходило на другой стороне. У меня ушло две недели, чтобы разобраться в этом. Компьютер RPC-4000 был оснащён современным устройством — индексным регистром. Он позволял писать программные циклы, внутри которых использовались индексированные инструкции. При каждом проходе через цикл число из регистра добавлялось к адресу инструкции, чтобы она ссылалась на следующую позицию в серии. Оставалось только инкрементировать индексный регистр при каждом проходе. Мэл этим не воспользовался. Вместо этого он вытягивал инструкцию в машинный регистр, добавлял к её адресу единицу и сохранял обратно. А затем исполнял модифицированную инструкцию прямо из регистра. Цикл был написан с учётом дополнительного времени на исполнение: как только инструкция завершалась, следующая оказывалась под считывающей головкой барабана. Но в цикле не было жульнической проверки. Спасительной подсказкой оказалось то, что был включён бит в индексном регистре — он располагался в коде команды между адресом и операционным кодом. Однако Мэл не использовал индексный регистр, оставляя его обнулённым.
Когда наступило прозрение, я едва не ослеп. Данные, с которыми он работал недалеко от верхних уровней памяти — крупнейшие адреса, на которые могли ссылаться инструкции, — Мэл разместил так, чтобы после обработки последней позиции инкрементирование адреса инструкции приводило к переполнению. При переносе к операционному коду прибавлялась единица, меняя его на следующий код в наборе: инструкцию перехода. Конечно же, эта следующая инструкция располагалась по нулевому адресу, и программа радостно туда отправлялась. Я не общался с Мэлом и не знаю, сдался ли он перед потоком перемен, который затопил с тех пор программирование. Предпочитаю думать, что не сдался. Я был настолько впечатлён, что перестал искать жульническую проверку и сказал Большому Боссу, что не могу её найти. Он не удивился. Когда я ушёл из компании, блэкджек-программа всё ещё жульничала, если включали нужный включатель, и это правильно, как мне кажется. Мне не нравилось хакать код Настоящего Программиста.
Исключительно проблема USB
Прямо из колледжа я устроился в компанию и в течение пяти месяцев работал над потребительским устройством, прежде чем его показали публике. Устройство работало под управлением Linux. И пока я свыкался с идеей баловства в пространстве ядра, меня выдернули на встречу по расстановке приоритетов в устранении багов. Многочисленных багов. Сотен багов. На каждом из которых написано: «это невозможно, как такое произошло?».
Они кричали: «Повреждение памяти!». Я думал: «Хоспади, исправляйте свои баги». Просматривая дампы падений, мы увидели… что это? Программа выполнила запрещённую инструкцию, объединяя две строки с помощью функции из стандартной библиотеки. Хм, странно… Следующий журнал: нельзя извлечь страницу из файла подкачки на устройстве, на котором вообще не выделено место для файла подкачки (кажется, я понимаю, почему мы не могли извлеч