Последняя часть подборки историй из интернета о том, как у багов иногда бывают совершенно невероятные проявления. Первая часть, вторая часть.
Маленький SSH, который (иногда) не мог
Это рассказ об одной из самых увлекательных охот на баг, в которой мне посчастливилось участвовать.
В компании AdGear Technologies Inc., где я работал, всё держалось на SSH. Мы применяли его для управления, мониторинга, развёртывания, сбора журналов, даже для потокового вещания в реальном времени. Этот протокол устойчивый и надёжный, обладает предсказуемостью нативного Unix-инструмента и просто работает.
Но однажды письма без какой-то определённой привязки ко времени или хосту подсказали нам, что протокол не работает.
Таймаут
На машинах в нашем лондонском ЦОДе возникали случайные сбои при отправке файлов журналов в ЦОД в Монреале. Эта задача периодически запускалась из 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 байтов. Все предыдущие пакеты были гораздо меньше.
Сравнив тот же пакет из сбойной отправки, в том виде, в каком он покинул Лондон и пришёл в Монреаль, мой взгляд за что-то зацепился. За что-то малозаметное, и я отмахнулся из-за усталости (был поздний вечер пятницы). Но после нескольких обновлений и сравнений мне уже не мерещилось.
0x0040: 0b7c aecc 1774 b770 ad92 0000 00b7 6563 .|...t.p......ec
0x0050: 6468 2d73 6861 322d 6e69 7374 7032 3536 dh-sha2-nistp256
0x0060: 2c65 6364 682d 7368 6132 2d6e 6973 7470 ,ecdh-sha2-nistp
0x0070: 3338 342c 6563 6468 2d73 6861 322d 6e69 384,ecdh-sha2-ni
0x0080: 7374 7035 3231 2c64 6966 6669 652d 6865 stp521,diffie-he
0x0090: 6c6c 6d61 6e2d 6772 6f75 702d 6578 6368 llman-group-exch
0x00a0: 616e 6765 2d73 6861 3235 362c 6469 6666 ange-sha256,diff
0x00b0: 6965 2d68 656c 6c6d 616e 2d67 726f 7570 ie-hellman-group
0x00c0: 2d65 7863 6861 6e67 652d 7368 6131 2c64 -exchange-sha1,d
0x00d0: 6966 6669 652d 6865 6c6c 6d61 6e2d 6772 iffie-hellman-gr
0x00e0: 6f75 7031 342d 7368 6131 2c64 6966 6669 oup14-sha1,diffi
0x00f0: 652d 6865 6c6c 6d61 6e2d 6772 6f75 7031 e-hellman-group1
0x0100: 2d73 6861 3100 0000 2373 7368 2d72 7361 -sha1...#SSH-rsa
0x0110: 2c73 7368 2d64 7373 2c65 6364 7361 2d73 ,SSH-dss,ecdsa-s
0x0120: 6861 322d 6e69 7374 7032 3536 0000 009d ha2-nistp256....
0x0130: 6165 7331 3238 2d63 7472 2c61 6573 3139 aes128-ctr,aes19
0x0140: 322d 6374 722c 6165 7332 3536 2d63 7472 2-ctr,aes256-ctr
0x0150: 2c61 7263 666f 7572 3235 362c 6172 6366 ,arcfour256,arcf
0x0160: 6f75 7231 3238 2c61 6573 3132 382d 6362 our128,aes128-cb
0x0170: 632c 3364 6573 2d63 6263 2c62 6c6f 7766 c,3des-cbc,blowf
0x0180: 6973 682d 6362 632c 6361 7374 3132 382d ish-cbc,cast128-
0x0190: 6362 632c 6165 7331 3932 2d63 6263 2c61 cbc,aes192-cbc,a
0x01a0: 6573 3235 362d 6362 632c 6172 6366 6f75 es256-cbc,arcfou
0x01b0: 722c 7269 6a6e 6461 656c 2d63 6263 406c r,rijndael-cbc@l
0x01c0: 7973 6174 6f72 2e6c 6975 2e73 6500 0000 ysator.liu.se...
0x01d0: 9d61 6573 3132 382d 6374 722c 6165 7331 .aes128-ctr,aes1
0x01e0: 3932 2d63 7472 2c61 6573 3235 362d 6374 92-ctr,aes256-ct
0x01f0: 722c 6172 6366 6f75 7232 3536 2c61 7263 r,arcfour256,arc
0x0200: 666f 7572 3132 382c 6165 7331 3238 2d63 four128,aes128-c
0x0210: 6263 2c33 6465 732d 6362 632c 626c 6f77 bc,3des-cbc,blow
0x0220: 6669 7368 2d63 6263 2c63 6173 7431 3238 fish-cbc,cast128
0x0230: 2d63 6263 2c61 6573 3139 322d 6362 632c -cbc,aes192-cbc,
0x0240: 6165 7332 3536 2d63 6263 2c61 7263 666f aes256-cbc,arcfo
0x0250: 7572 2c72 696a 6e64 6165 6c2d 6362 6340 ur,rijndael-cbc@
0x0260: 6c79 7361 746f 722e 6c69 752e 7365 0000 lysator.liu.se..
0x0270: 00a7 686d 6163 2d6d 6435 2c68 6d61 632d ..hmac-md5,hmac-
0x0280: 7368 6131 2c75 6d61 632d 3634 406f 7065 sha1,umac-64@ope
0x0290: 6e73 7368 2e63 6f6d 2c68 6d61 632d 7368 nSSH.com,hmac-sh
0x02a0: 6132 2d32 3536 2c68 6d61 632d 7368 6132 a2-256,hmac-sha2
0x02b0: 2d32 3536 2d39 362c 686d 6163 2d73 6861 -256-96,hmac-sha
0x02c0: 322d 3531 322c 686d 6163 2d73 6861 322d 2-512,hmac-sha2-
0x02d0: 3531 322d 3936 2c68 6d61 632d 7269 7065 512-96,hmac-ripe
0x02e0: 6d64 3136 302c 686d 6163 2d72 6970 656d md160,hmac-ripem
0x02f0: 6431 3630 406f 7065 6e73 7368 2e63 6f6d d160@openSSH.com
0x0300: 2c68 6d61 632d 7368 6131 2d39 362c 686d ,hmac-sha1-96,hm
0x0310: 6163 2d6d 6435 2d39 3600 0000 a768 6d61 ac-md5-96....hma
0x0320: 632d 6d64 352c 686d 6163 2d73 6861 312c c-md5,hmac-sha1,
0x0330: 756d 6163 2d36 3440 6f70 656e 7373 682e umac-64@openSSH.
0x0340: 636f 6d2c 686d 6163 2d73 6861 322d 3235 com,hmac-sha2-25
0x0350: 362c 686d 6163 2d73 6861 322d 3235 362d 6,hmac-sha2-256-
0x0360: 3936 2c68 6d61 632d 7368 6132 2d35 3132 96,hmac-sha2-512
0x0370: 2c68 6d61 632d 7368 6132 2d35 3132 2d39 ,hmac-sha2-512-9
0x0380: 362c 686d 6163 2d72 6970 656d 6431 3630 6,hmac-ripemd160
0x0390: 2c68 6d61 632d 7269 7065 6d64 3136 3040 ,hmac-ripemd160@
0x03a0: 6f70 656e 7373 682e 636f 6d2c 686d 6163 openSSH.com,hmac
0x03b0: 2d73 6861 312d 3936 2c68 6d61 632d 6d64 -sha1-96,hmac-md
0x03c0: 352d 3936 0000 0015 6e6f 6e65 2c7a 6c69 5-96....none,zli
0x03d0: 6240 6f70 656e 7373 682e 636f 6d00 0000 b@openSSH.com...
0x03e0: 156e 6f6e 652c 7a6c 6962 406f 7065 6e73 .none,zlib@opens
0x03f0: 7368 2e63 6f6d 0000 0000 0000 0000 0000 sh.com..........
0x0400: 0000 0000 0000 0000 0000 0000 ............
0x0040: 0b7c aecc 1774 b770 ad92 0000 00b7 6563 .|...t.p......ec
0x0050: 6468 2d73 6861 322d 6e69 7374 7032 3536 dh-sha2-nistp256
0x0060: 2c65 6364 682d 7368 6132 2d6e 6973 7470 ,ecdh-sha2-nistp
0x0070: 3338 342c 6563 6468 2d73 6861 322d 6e69 384,ecdh-sha2-ni
0x0080: 7374 7035 3231 2c64 6966 6669 652d 6865 stp521,diffie-he
0x0090: 6c6c 6d61 6e2d 6772 6f75 702d 6578 6368 llman-group-exch
0x00a0: 616e 6765 2d73 6861 3235 362c 6469 6666 ange-sha256,diff
0x00b0: 6965 2d68 656c 6c6d 616e 2d67 726f 7570 ie-hellman-group
0x00c0: 2d65 7863 6861 6e67 652d 7368 6131 2c64 -exchange-sha1,d
0x00d0: 6966 6669 652d 6865 6c6c 6d61 6e2d 6772 iffie-hellman-gr
0x00e0: 6f75 7031 342d 7368 6131 2c64 6966 6669 oup14-sha1,diffi
0x00f0: 652d 6865 6c6c 6d61 6e2d 6772 6f75 7031 e-hellman-group1
0x0100: 2d73 6861 3100 0000 2373 7368 2d72 7361 -sha1...#SSH-rsa
0x0110: 2c73 7368 2d64 7373 2c65 6364 7361 2d73 ,SSH-dss,ecdsa-s
0x0120: 6861 322d 6e69 7374 7032 3536 0000 009d ha2-nistp256....
0x0130: 6165 7331 3238 2d63 7472 2c61 6573 3139 aes128-ctr,aes19
0x0140: 322d 6374 722c 6165 7332 3536 2d63 7472 2-ctr,aes256-ctr
0x0150: 2c61 7263 666f 7572 3235 362c 6172 6366 ,arcfour256,arcf
0x0160: 6f75 7231 3238 2c61 6573 3132 382d 6362 our128,aes128-cb
0x0170: 632c 3364 6573 2d63 6263 2c62 6c6f 7766 c,3des-cbc,blowf
0x0180: 6973 682d 6362 632c 6361 7374 3132 382d ish-cbc,cast128-
0x0190: 6362 632c 6165 7331 3932 2d63 6263 2c61 cbc,aes192-cbc,a
0x01a0: 6573 3235 362d 6362 632c 6172 6366 6f75 es256-cbc,arcfou
0x01b0: 722c 7269 6a6e 6461 656c 2d63 6263 406c r,rijndael-cbc@l
0x01c0: 7973 6174 6f72 2e6c 6975 2e73 6500 0000 ysator.liu.se...
0x01d0: 9d61 6573 3132 382d 6374 722c 6165 7331 .aes128-ctr,aes1
0x01e0: 3932 2d63 7472 2c61 6573 3235 362d 6374 92-ctr,aes256-ct
0x01f0: 722c 6172 6366 6f75 7232 3536 2c61 7263 r,arcfour256,arc
0x0200: 666f 7572 3132 382c 6165 7331 3238 2d63 four128,aes128-c
0x0210: 6263 2c33 6465 732d 6362 632c 626c 6f77 bc,3des-cbc,blow
0x0220: 6669 7368 2d63 6263 2c63 6173 7431 3238 fish-cbc,cast128
0x0230: 2d63 6263 2c61 6573 3139 322d 6362 632c -cbc,aes192-cbc,
0x0240: 6165 7332 3536 2d63 6263 2c61 7263 666f aes256-cbc,arcfo
0x0250: 7572 2c72 696a 6e64 6165 6c2d 6362 7340 ur,rijndael-cbs@
0x0260: 6c79 7361 746f 722e 6c69 752e 7365 1000 lysator.liu.se..
0x0270: 00a7 686d 6163 2d6d 6435 2c68 6d61 732d ..hmac-md5,hmas-
0x0280: 7368 6131 2c75 6d61 632d 3634 406f 7065 sha1,umac-64@ope
0x0290: 6e73 7368 2e63 6f6d 2c68 6d61 632d 7368 nSSH.com,hmac-sh
0x02a0: 6132 2d32 3536 2c68 6d61 632d 7368 7132 a2-256,hmac-shq2
0x02b0: 2d32 3536 2d39 362c 686d 6163 2d73 7861 -256-96,hmac-sxa
0x02c0: 322d 3531 322c 686d 6163 2d73 6861 322d 2-512,hmac-sha2-
0x02d0: 3531 322d 3936 2c68 6d61 632d 7269 7065 512-96,hmac-ripe
0x02e0: 6d64 3136 302c 686d 6163 2d72 6970 756d md160,hmac-ripum
0x02f0: 6431 3630 406f 7065 6e73 7368 2e63 7f6d d160@openSSH.c.m
0x0300: 2c68 6d61 632d 7368 6131 2d39 362c 786d ,hmac-sha1-96,xm
0x0310: 6163 2d6d 6435 2d39 3600 0000 a768 7d61 ac-md5-96....h}a
0x0320: 632d 6d64 352c 686d 6163 2d73 6861 312c c-md5,hmac-sha1,
0x0330: 756d 6163 2d36 3440 6f70 656e 7373 782e umac-64@openssx.
0x0340: 636f 6d2c 686d 6163 2d73 6861 322d 3235 com,hmac-sha2-25
0x0350: 362c 686d 6163 2d73 6861 322d 3235 362d 6,hmac-sha2-256-
0x0360: 3936 2c68 6d61 632d 7368 6132 2d35 3132 96,hmac-sha2-512
0x0370: 2c68 6d61 632d 7368 6132 2d35 3132 3d39 ,hmac-sha2-512=9
0x0380: 362c 686d 6163 2d72 6970 656d 6431 3630 6,hmac-ripemd160
0x0390: 2c68 6d61 632d 7269 7065 6d64 3136 3040 ,hmac-ripemd160@
0x03a0: 6f70 656e 7373 682e 636f 6d2c 686d 7163 openSSH.com,hmqc
0x03b0: 2d73 6861 312d 3936 2c68 6d61 632d 7d64 -sha1-96,hmac-}d
0x03c0: 352d 3936 0000 0015 6e6f 6e65 2c7a 7c69 5-96....none,z|i
0x03d0: 6240 6f70 656e 7373 682e 636f 6d00 0000 b@openSSH.com...
0x03e0: 156e 6f6e 652c 7a6c 6962 406f 7065 6e73 .none,zlib@opens
0x03f0: 7368 2e63 6f6d 0000 0000 0000 0000 0000 sh.com..........
0x0400: 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
Учитывая фактор случайности и настройку в цикле повторных попыток, я получил несколько пакетов, которые развеяли все сомнения относительно предыдущих умозаключений. Вот часть одного из пакетов:
0x0210 .....
0x0220 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0230 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0240 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0250 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0260 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0270 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0280 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0290 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02a0 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02b0 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02c0 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02d0 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02e0 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02f0 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0300 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0310 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0320 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0330 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0340 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0350 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0360 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0370 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0380 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0390 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x03a0 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x03b0 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x03c0 0000 0000 0000 0000 0000 0000 0000 1000 ................
0x03d0 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x03e0 .....
Воспроизведя баг, мне нужно было найти тот из 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, тоже на барабанной памяти, намного улучшенный, более крупный и быстрый. Магнитные сердечники стоили слишком дорого, да они и не выдержали конкуренции (поэтому вы не слышали ни об этой компании, ни о её компьютерах). Меня наняли, чтобы я написал FORTRAN-компилятор для этого нового чуда, а Мэл был моим гидом по его возможностям. Мэл не одобрял компиляторы. «Что хорошего в том, что программа не может переписать собственный код?», — спрашивал он. Мэл написал на шестнадцатеричном коде самую популярную программу компании. Она работала на LGP-30 и играла в блэкджек с потенциальными покупателями на компьютерных выставках. Это всегда оказывало драматический эффект. Стенд с LGP-30 выставлялся на каждой выставке, а продавцы IBM собирались вокруг и беседовали друг с другом. Помогало ли это продавать компьютеры? Этот вопрос мы никогда не обсуждали.
В обязанности Мэла входило переписывание блэкджек-программы под RPC-4000. (Портирование? Что это такое?) У нового компьютера была схема адресации «один-плюс-один»: у каждой машинной инструкции кроме кода операции и адреса нужного операнда был ещё и второй адрес, который показывал, где на вращающемся магнитном барабане записана следующая инструкция. То есть после каждой инструкции шло GO TO! Набейте это в трубку Pascal и выкурите.
Мэл любил RPC-4000, потому что мог оптимизировать свой код: размещать инструкции на барабане так, чтобы как только одна завершалась, вторая сразу оказывалась под «считывающей головкой» и была готова к немедленному исполнению. Для этого была написана программа, «оптимизирующий ассемблер», но Мэл отказывался ею пользоваться. «Никогда не знаешь, куда она положит данные», — объяснял он, — «поэтому приходится использовать отдельные константы». Я понял суть этой фразы гораздо позже. Поскольку Мэл знал числовые значения всех операционных кодов и присваивал в барабанной памяти собственные адреса, то каждую написанную им инструкцию можно было считать числовой константой. К примеру, он мог выбрать более раннюю инструкцию «сложения» и умножить на неё, если она имела подходящее числовое значение. Его код мало кто мог изменять. Я сравнивал вручную оптимизированные Мэлом программы с тем же кодом, который был обработан оптимизирующим ассемблером, и код Мэла всегда исполнялся быстрее. Дело в том, что метод построения архитектуры «сверху вниз» ещё не изобрели, да Мэл всё равно не пользовался бы им. Сначала он писал внутренние части своих программных циклов, чтобы те первыми получали оптимальные адреса на барабане. А оптимизирующий ассемблер был на такое неспособен. Мэл никогда не писал циклы с задержкой по времени, даже когда неповоротливый Flexowriter требовал делать задержку между выводами символов. Мэл просто размещал инструкции на барабане так, чтобы в момент, когда нужно было считать следующую инструкцию, она проходила мимо считывающей головки, и барабану требовалось сделать ещё один оборот, чтобы её найти. Мэл нашёл для этой процедуры неподражаемый термин. Слово «оптимальный» (optimum) имеет абсолютное значение, как и «уникальный», поэтому в разговорной речи их стали часто делать относительными: «не совсем оптимально», или «менее оптимально», или «не очень оптимально». Мэл называл места на барабане с наибольшим временем задержки «самый пессимум» (pessimum — наихудшие условия среды, переносимые организмом).
Завершив работу над блэкджек-программой и запустив её («Даже инициализатор оптимизирован», — гордо сказал он), Мэл получил от отдела продаж заявку на внесение изменений. За перемешивание карт и сдачи из колоды в программе отвечал элегантный (оптимизированный) генератор случайных чисел. И кто-то из продажников посчитал это слишком честным, потому что иногда покупатели проигрывали. Они попросили Мэла изменить программу так, чтобы с помощью сенсорного включателя на консоли можно было изменить шансы игрока и позволить покупателю выиграть. Мэл отказался. Он считал это нечестным — так оно и было, — и что это посягает на его нравственность программиста — так оно и было, — поэтому отказался в этом участвовать. Мэла уговаривал начальник отдела продаж, и Большой Босс, и коллеги-программисты по настоянию Босса. Наконец Мэл сдался и написал код, но сделал жульническую проверку наоборот: когда включатель был включён, программа жульничала и всегда выигрывала. Мэл был в восторге от своего решения. Он утверждал, что его подсознание проявило неуправляемую этичность и наотрез отказался исправлять программу. Когда Мэл ушёл из компании ради более высокого заработка, Большой Босс попросил меня взглянуть на код и сказать, смогу ли я найти модуль проверки и поменять порядок его работы. Я неохотно согласился.
Разбирательство с кодом Мэла было настоящим приключением. Мне часто казалось, что программирование — это вид искусства, настоящую ценность которого может оценить лишь тот, кто разбирается в этом загадочном искусстве. В нём встречаются настоящие драгоценности и блестящие ходы, самой природой процесса скрытые от человеческого взгляда и восхищения, иногда навсегда. Можно многое узнать о человеке, просто читая его код, даже шестнадцатеричный. Думаю, Мэл был непризнанным гением. Пожалуй, самым сильным потрясением стал найденный мной невинный цикл, в котором не было жульнической проверки. Нет проверки. Нет.
Здравый смысл подсказывал, что это должен быть закрытый цикл, внутри которого циркулирует программа, вечно, бесконечно. Однако программное управление успешно проходило через него и безопасно выходило на другой стороне. У меня ушло две недели, чтобы разобраться в этом. Компьютер RPC-4000 был оснащён современным устройством — индексным регистром. Он позволял писать программные циклы, внутри которых использовались индексированные инструкции. При каждом проходе через цикл число из регистра добавлялось к адресу инструкции, чтобы она ссылалась на следующую позицию в серии. Оставалось только инкрементировать индексный регистр при каждом проходе. Мэл этим не воспользовался. Вместо этого он вытягивал инструкцию в машинный регистр, добавлял к её адресу единицу и сохранял обратно. А затем исполнял модифицированную инструкцию прямо из регистра. Цикл был написан с учётом дополнительного времени на исполнение: как только инструкция завершалась, следующая оказывалась под считывающей головкой барабана. Но в цикле не было жульнической проверки. Спасительной подсказкой оказалось то, что был включён бит в индексном регистре — он располагался в коде команды между адресом и операционным кодом. Однако Мэл не использовал индексный регистр, оставляя его обнулённым.
Когда наступило прозрение, я едва не ослеп. Данные, с которыми он работал недалеко от верхних уровней памяти — крупнейшие адреса, на которые могли ссылаться инструкции, — Мэл разместил так, чтобы после обработки последней позиции инкрементирование адреса инструкции приводило к переполнению. При переносе к операционному коду прибавлялась единица, меняя его на следующий код в наборе: инструкцию перехода. Конечно же, эта следующая инструкция располагалась по нулевому адресу, и программа радостно туда отправлялась. Я не общался с Мэлом и не знаю, сдался ли он перед потоком перемен, который затопил с тех пор программирование. Предпочитаю думать, что не сдался. Я был настолько впечатлён, что перестал искать жульническую проверку и сказал Большому Боссу, что не могу её найти. Он не удивился. Когда я ушёл из компании, блэкджек-программа всё ещё жульничала, если включали нужный включатель, и это правильно, как мне кажется. Мне не нравилось хакать код Настоящего Программиста.
Исключительно проблема USB
Прямо из колледжа я устроился в компанию и в течение пяти месяцев работал над потребительским устройством, прежде чем его показали публике. Устройство работало под управлением Linux. И пока я свыкался с идеей баловства в пространстве ядра, меня выдернули на встречу по расстановке приоритетов в устранении багов. Многочисленных багов. Сотен багов. На каждом из которых написано: «это невозможно, как такое произошло?».
Они кричали: «Повреждение памяти!». Я думал: «Хоспади, исправляйте свои баги». Просматривая дампы падений, мы увидели… что это? Программа выполнила запрещённую инструкцию, объединяя две строки с помощью функции из стандартной библиотеки. Хм, странно… Следующий журнал: нельзя извлечь страницу из файла подкачки на устройстве, на котором вообще не выделено место для файла подкачки (кажется, я понимаю, почему мы не могли извлечь страницу!).
Когда-то я написал короткую программу. Она выделяла 80 % системной памяти под один массив и записывала в него последовательные целые числа. Затем ждала, чтобы нажали Enter, и проверяла, не изменилось ли содержимое массива. Теперь я загрузил эту программу, подождал 30 секунд, а затем запустил проверку. Никаких проблем. Попытался ещё несколько раз — ха, я знал, что никакого повреждения памяти нет! Я выдернул отладочный кабель (USB), секунд через 10 несколько раз быстро вставил и выдернул, затем снова вставил. Бам! 90 ошибок.
Твою же.
Ладно, придётся повозиться с USB-портом. Получается, проблема связана с ним? Не похоже, что драйвер USB реализует волшебный bit fairy-алгоритм, который случайным образом разбрасывает битовые ошибки. Наверное, проблема с железом? Нет, не с ним, но это не помешало нам творить всякие непотребства с USB-портом. Позвали инженеров, которые давно переключились на другой продукт, и теперь они ломали голову над проблемой. Я не помню, сколько времени мы потратили, доказывая себе, что с аппаратной частью был полный, полный, пооооолный порядок. Заземление было в порядке, напряжение стабильное, часы шли точно, а схема DDR-линий была настолько идеальной, что вы заплакали бы от счастья, увидев её.
Устройства, которые тестировались инженерами, становились всё более нестабильными. Я предположил, что аппарат может загрузить данные в память, получить битовые ошибки, а затем выгрузить обратно во флеш-память, возможно даже не в то место (таблица страниц часто повреждалась, так что можно было допустить, что это происходит и со структурами отслеживания файлов. Содержимое могло записываться в неправильные места, а структуры файловой системы могли ломаться, и т.д.) Со временем устройства деградировали настолько, что уже не могли надёжно загрузиться. Наконец один из инженеров сломался и перезаписал в память образ, который лежал у него на ноутбуке. Этот образ был относительно древним.
— Чувак. Дело в программном обеспечении.
— Что?!?!?! Уверяю, мы не писали bit fairy!
Нет: он залил сборку трёхмесячной давности, и проблема исчезла. В этот момент я чувствовал себя ответственным за то, что вовлёк кучу людей в очень долгую и бессмысленную затею, поэтому остался на ночь и провёл бинарный поиск по всем патчам за прошедшие месяцы (на изучение полных сборок целой ОС ушло больше времени, чем мне хотелось бы…).
Так что это был за волшебный патч? Кто-то добавил в ядро драйвер для чипа, который мы анализировали. Этого чипа в устройстве не было.
Ха! Мы нашли ведьму! СЖЕЧЬ ЕЁ!
Многие объявили, что задача решена. Они были счастливы, что в ближайшем релизе можно откатить патч и жить дальше. Мы откатили его с крайней придирчивостью, собрали образ, протестировали, всё было хорошо. Мы не предполагали, что через несколько дней тот же дефект появится в ядре.
Погодите. Если чипа не было на плате, как нам помешал драйвер? Я запускал lsmod, драйвер не был загружен… «Да и ладно, какая разница, удалю файл модуля и перезагружу. Нифига, проблема осталась. Это ненормально...»
Теперь я был один и наблюдал за происходившей чертовщиной. Начал внимательно анализировать патч. Это был милый файл в 10 тыс. строк на С, который нам предоставил производитель чипа. Описывать его словом «хаос» было бы слишком снисходительно (справедливости ради, через несколько недель они прислали нам гораздо более продуманный драйвер). Поковырявшись немного, я решил, что в драйвере не было реализовано битовое-жонглирование-ради-забавы. Так в чём же дело? 48 байтов из пяти строк кода. Маленькая структура в загрузочном файле, в которой говорится, по какому адресу шины нужно искать чип. Я удалил большую часть драйвера, но оставил в нём другую структуру. Проблема не исчезла.
Итак, мальчики и девочки, у нас проблема с выравниванием! Каким-то образом эта 48-байтная структура что-то двигает в памяти, и это приводит к ошибкам. Я выяснил, что проблема возникает, когда помещаешь в файл что-нибудь больше 32 и меньше 64 байтов. Это знание не слишком помогло, но хотя бы создавало ощущение прогресса.
Сборка ядра выдавала аккуратный файл System.map. В нём перечислялось, где в виртуальном адресном пространстве ядра находятся все переменные, скомпилированные в ядре. Я выяснил, что моя маленькая структура находится посреди раздела «.data». Этот раздел заполнен инициализированными переменными, так что когда бинарник ядра распаковывался в памяти, он записывал все эти переменные из скомпилированного образа. Пользуясь System.map как справочником, я реализовал довольно бестолковый бинарный поиск. По большей части я искал по линкерам разных С-файлов. Я нашёл переменную, с которой нужно было сравнивать; нашёл файл ядра, который её содержит; положил рядом в случайном файле мою волшебную структуру и начал смотреть, проявится ли снова проблема.
Процедура поиска дошла до последних нескольких элементов .data и вернулась с пустыми руками. В памяти с инициализированными переменными не было нужных данных. Полистав дальше файл System.map, я увидел, что не обратил внимания на целый раздел .bss, в который попадали неинициализированные переменные. Наученный прежними ошибками, я сначала проверил начало и конец. Конечно, неинициализированная переменная в начале раздела приводила к ошибкам, а переменная в конце раздела — не приводила. Поиск виновника был лишь делом времени. Переменной, чьё перемещение приводило к проблеме, был…
Указатель функции?!
Как, чёрт побери, выравнивание указателя функции рушит нашу систему? В архитектуре ARM нельзя читать слова при обращении без выравнивания, то есть каждую 32-битную переменную нужно класть в память по адресу, кратному 4. Указатель функции не исключение, он всегда получает минимальный адрес. Оказывается, в нашей проблемной ситуации адрес был кратен 2n, большей либо равной 64. Любое значение меньше этого порога — и проблема пропадала. С выравниванием указателя тоже был порядок.
Не бывает слишком хорошего выравнивания. По крайней мере, не было до возникновения этого бага.
Теперь этот указатель функции не был «дедовским» указателем. Он ссылался на что-то особенное. В SRAM процессора была область, которую мы могли использовать для связанных с загрузкой задач, если не могли использовать RAM. Чтобы экономить энергию во время простоя, мы скопировали в эту область подпрограмму, задали особый указатель, который ссылался на неё, а потом его вызывали. Что делала подпрограмма? Давайте взглянем на ассемблер. Я не специалист по ARM-ассемблеру, но комментарии были достаточно красноречивы.
// Вычисляет адрес привязанного к памяти управляющего регистра...
...
// Теперь выключаем контроллер памяти и переводим LPDDR в режим самоообновления
ЧТО вы делаете?! Быстро же вы перешли от базовых операций с регистрами к отключению контроллера памяти. Я отправил письмо производителю, который написал подпрограмму, и спросил, не упустили ли они что-то.
Через три дня мне пришёл ответ в стиле «Ах да, там должен быть барьер памяти». Получается, что из-за структуры их L2-кэша им пришлось бы дополнительно поддерживать TLB, если бы мы случайно записали в адрес памяти, кратный 64. В таких случаях мы всё ещё можем использовать оперативную память при выключенном контроллере.
Учитывая, что для выравнивания переменных нужна минимальная кратность 4, и что для последней записи не может быть кратности 64 или больше, при каждом компилировании одна шестнадцатая часть данных оказывалась совершенно непригодной для использования системой.
В конце концов мы отгрузили надёжный продукт с барьером памяти, и покупателям он понравился. Да, и если вам интересно, я не мог этого заметить с помощью USB-кабеля, потому что мы не могли войти в режим низкого энергопотребления из-за использования USB. Это исключительно проблема USB.
Неверное сообщение об ошибке
В последние часы 17 сентября 1996, за день до запланированного запуска сервиса WebTV, наша группа собралась в эксплуатационном центре в Пало-Альто. Поблизости болталась толпа сисадминов-сетевиков и разработчиков сервисного ПО, чтобы стать свидетелями официального запуска.
Когда пробил назначенный час, один из сетевиков начал регистрироваться на своём устройстве WebTV. Мы понимали, что хорошие ники быстро закончатся, поэтому важно было зарегистрироваться до того, как это начнут делать пользователи. К тому же было приятно оказаться в числе первых, кто зарегистрируется на первом «настоящем» сервисе. До этого все аккаунты были «одноразовыми» тестовыми.
Несколько человек столпились вокруг, глядя, как он набирает на клавиатуре, ощущая головокружение от предвкушения и недосыпа. Брайс ввёл своё имя, адрес и другую информацию, а затем начал печатать ник. Это было его имя для адреса электронной почты. Он набрал «jazz», то есть его почта должна была быть «jazz@webtv.net». Когда он нажал Enter на беспроводной клавиатуре, мы услышали характерный звук, обозначающий появление сообщения об ошибке. Все посмотрели на экран.
Чтобы понять произошедшее далее, важно кое-что знать о работе сервиса. WebTV позиционировался как семейный, поэтому нужно было проверять на сквернословие и отфильтровывать пользовательские имена и прочую видимую для пользователей информацию. Всё выловить невозможно, но очевидные вещи отфильтровать несложно.
Пользовательские имена сравнивались со списком регулярных выражений, которые позволяли сравнивать с шаблоном. Например, «fu.*bar» будет сравнивать со всеми именами, начинающимися с «fu» и заканчивающимися на «bar». Если тщательно подобрать паттерны, можно выловить и отклонить такие вопиющие варианты, как «shitake» и «matsushita», в которые встроены ругательства.
Тот же механизм использовался для того, чтобы пользователи не могли выбирать «запрещённые» имена вроде «postmaster», «root», «admin» и «help». У нас был такой текстовый файл:
admin.*
Имя пользователя не может начинаться с "admin".
postmaster
Вы не postmaster.
poop
Это плохое слово.
weenie
Это плохое слово.
Каждая запись состояла из двух строк. Первая была регулярным выражением, с которым проводилось сравнение, а вторая строка была сообщением об ошибке, которое показывалось пользователю. Система читала файл сразу по две строки, и когда пользователь вводил имя, оно сравнивалось со всеми регулярными выражениями. Для первого найденного совпадения выводилось сообщение об ошибке. Если совпадений не было, пользовательское имя принималось.
Код, читавший файл, умел пропускать комментарии. Но он не умел обрабатывать пустые строки.
Кто-то внёс изменения в файл с ругательствами, попутно добавив одну пустую строку после «зарезервированных» имён и перед ругательствами. Когда код читал список, он принимал пустую строку за регулярное выражение, а следующее за ней слово — за сообщение об ошибке. А выражение в виде пустой строки совпадает с чем угодно.
Полночь. Мы все немного на взводе. Брайс пишет имя, а система отвечает простым сообщением:
Мы начали истерически ржать. К нам подошли другие, чтобы узнать, что происходит. Мы показали на экран. Они начали истерически ржать.
В это время в другом здании Марк Армстронг (отвечавший за QA) вместе с Брюсом Ликом (одним из основателей компании) сидели перед стойкой из шестнадцати приставок WebTV. Эта стойка, прозванная «racksville», была подключена через видеомультиплексор к большому телевизору, одновременно показывающему изображения со всех 16 приставок. Марк и Брюс начали регистрировать приставки, пользуясь клавиатурой с инфракрасным передатчиком. Мы позвонили им по интеркому:
— Как у вас идёт?
— Всё отлично.
— А, хорошо. Вы могли кое-что заметить при регистрации.
— Да? Мы не заметили ничего странного.
— Заметите.
— Ладно. Вводим почтовый индекс… пока всё нормально. ОГО!!!
На изображениях со всех 16 приставок возникло дружелюбное сообщение. Начальники предположили, что нам, быть может, стоит поскорее исправить этот глюк. Это показалось нам отличной идеей.
Мы исправили файл, и научили код распознавать и игнорировать пустые строки. Насколько я знаю, WebTV не сказал ни одному клиенту «f--k».
Проблема с падением Xbox
В то время команда работала над одной из первых игр для совершенно новой приставки под названием Xbox. Когда финальное тестирование ускорили, QA запустили три приставки из установочной партии, чтобы гонять ночью автоматизированные тесты. Если вчерашняя сборка игры утром всё ещё тестировалась, это говорило о её стабильности.
К сожалению, утром одна из консолей упала. Падения — это всегда плохо, но это был на редкость плохой случай: что-то, исполнявшееся видеокартой, обрушило всю систему. Диагностировать проблемы с видеокартой тяжело: никаких отладчиков, никакой трассировки стека, никакой отладки с помощью printf. Можно только читать код и экспериментировать.
Так началась Охота на Баг. Каждый день ведущие инженеры просматривали имеющиеся улики, выдвигали гипотезы и исключали возможности. Каждую ночь QA получали «случайное» падение без какой-либо причины. «Это невозможно», «Как это происходит?», «Может, это баг в компиляторе?» — все самые популярные хиты.
На машине инженеров игра работала идеально, по много дней. Но это было слабым утешением, потому что близился дедлайн отправки игры в печать и отгрузки в магазины.
К счастью, скоро удалось найти закономерность, хотя и довольно странную. Игра падала только ночью и только на одной из трёх приставок. Начали искать различия между ними. Дело было не в кабеле питания. Не в контроллерах. Не в порядке записи DVD. Переносили приставку на свой стол — не падает. Ставили обратно — падает. Дело было в специфическом стенде, который использовали QA.
Теперь процесс исключения факторов требовал исключить все переменные. В конце концов, отчаявшись, инженер попытался поменять приставки на столе местами.
Оказалось, сбойной была не конкретная приставка. Падала любая приставка, стоявшая на этом столе. Посреди ночи. Иногда ради науки приходится поступать странно, и это был один из таких случаев. Инженер стоически уселся в кресло, обложился банками с Red Bull, и Охота на Баг превратилась в Наблюдение за Багом. Инженер поклялся, что будет смотреть, как на стоящих на этом проклятом столе приставках выполняются автоматизированные тесты, пока не увидит сбой собственными глазами.
Ночь тянулась медленно, затем быстро, и наконец наступил рассвет. Игра продолжала работать. Это вдохновляло. Стало подниматься солнце.
И тут наконец-то произошло кое-что интересное: на стол упал луч восходящего солнца. Минута за минутой луч полз по столу к приставкам, его тёплое сияние тихо обволакивало чёрный купол приставки.
Которая быстро упала.
У первых Xbox оказалась проблема: видеокарта могла сбоить, если температура приставки достигала определённого значения. Программное обеспечение было ни при чём. Об аппаратной проблеме сообщили, игру выпустили, а Red Bull заменили на пиво. Ну ладно, будем честны, на виски. Один: ноль в пользу науки.
Автор: NIX
