Гейзенбаг — это худшее, что может произойти. В описанном ниже исследовании, которое растянулось на 20 месяцев, мы уже дошли до того, что начали искать аппаратные проблемы, ошибки в компиляторах, линкерах и делать другие вещи, которые стоит делать в самую последнюю очередь. Обычно переводить стрелки подобным образом не нужно (баг скорее всего у вас в коде), но в данном случае нам наоборот — не хватило глобальности виденья проблемы. Да, мы действительно нашли баг в линкере, но кроме него мы ещё нашли и баг в ядре Windows.

В сентябре 2016 года мы стали замечать случайно происходящие ошибки при сборке Хрома — 3 билда из 200 провалились из-за крэша процесса protoc.exe. Это один из бинарников, который при сборке Хрома сначала собирается сам, а затем запускается для генерации заголовочных файлов других компонентов. Но вместо этого он падал с ошибкой «access violation».

Разработчики, которые исследовали данную проблему, понимали, что происходит что-то странное, но не могли воспроизвести проблему локально, так что им пришлось делать догадки о её причинах. Несколько исправлений были сделаны «наугад» — изменение порядка аргументов, явное добавление зависимостей. Последнее вроде бы сработало — проблемы пропали.

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

Локальное воспроизведение проблемы

Я присоединился к данному исследованию почти случайно — мне однажды удалось воспроизвести баг на моей машине. Я запустил «плохой» бинарник под отладчиком и увидел следующее:

…
00000001400010A1 00 00  add byte ptr [rax],al
00000001400010A3 00 00  add byte ptr [rax],al
mainCRTStartup:
00000001400010A5 00 00  add byte ptr [rax],al
00000001400010A7 00 00  add byte ptr [rax],al
…

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

Я удалил «плохой» бинарник и слинковал его ещё раз — в этот раз последовательности нулевых байт были заменены корректными инструкциями и он больше не падал. Длинный массив нулевых байтов принадлежал к коду, который создал инкрементальный линкер VC++ для того, чтобы как-то там удобнее для него перемещать функции. В этот момент стало очевидно, что мы нашли баг в инкрементальном линкере, правда? Совсем отключить его было нельзя — инкрементальная компоновка является важной частью стратегии оптимизации времени сборки больших бинарников (вроде нашего chrome.dll). Но мы могли отключить его для мелких бинарников вроде protoc.exe и ему подобных. Так мы и сделали.

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

Двумя неделями позже на моём компьютере снова упала сборка Хрома. И это уже была сборка, включавшая предыдущий фикс с отключенной инкрементальной линковкой для protoc.exe. В этот раз в бинарнике снова был массив нулевых байт вместо корректных кодовых инструкций, но находился он уже в коде, к созданию которого инкрементальный линкер не имел отношения.

Более того, эти нулевые байты были вставлены в код уже вообще другим инструментом — к этому моменту я переключился с линкера от Microsoft на lld-link (use_lld=true в параметрах сборки). Более того, в этот раз я и компилятор использовал другой (clang вместо VC++). Получается, что замена вообще всего сборочного тулчейна не помогла исправить данную проблему. А это означает, что проблема не в тулчейне. К этому моменту наилучшим объяснением происходящего вообще начала казаться массовая истерия.

Но нет, у нас есть наука!

Не зря инструменты и способы разработки и отладки совершенствовались много лет. У нас есть кое-что, что мы можем противопоставить гейзенбагам. Баг воспроизводился на моём компьютере чаще, чем на остальных, поскольку я тогда занимался оптимизацией сборки Хрома и этих самых сборок я делал значительно больше среднестатистического программиста (даже намного больше других разработчиков Хрома). Ну, если для воспроизведения бага нужно много сборок — так давайте сделаем МНОГО сборок.

Я изменил мои скрипты для сборки Хрома снова и снова в бесконечном цикле, который должен остановиться лишь тогда, когда баг даст о себе знать. С системой распределенной сборки и минимальным уровнем генерации символьной информации я мог (при сопутствующей удаче) собирать Хром до 12 раз в час. При такой частоте сборок даже столь редко воспроизводимый баг стал стабильно происходить хотя бы раз в полдня. Кроме него, конечно, начали вылезать и другие баги (зомби!), но это отдельная история.

А потом мне вдруг повезло. Однажды утром я залогинился на свой компьютер, который всю ночь гонял сборку Хрома и увидел, что модуль genmodule.exe упал (а падали каждый раз разные бинарники). Поскольку сборка при этом была остановлена — у меня был на диске ровно тот же бинарник, чей запуск при сборке вызвал падение. И я решил запустить его снова — всегда интереснее увидеть «живой» крэш, чем копаться в старых дампах. Но в этот раз бинарник не упал.

У меня был крэшдамп (поскольку Windows Error Reporting на моём компьютере был настроен на сохранение локальных крэшдампов, что я советую сделать всем Windows-разработчикам). В этом крэшдампе я увидел уже знакомую мне последовательность нулей в месте выполнения кода. Эта последовательность инструкций ну никак, ни в одной теории не могла выполниться без ошибки. Я запустил бинарник genmodule.exe ещё раз под отладчиком, дошел до того же адреса — и там был нормальный код, никаких нулей.

Я загрузил крэшдамп в WinDbg и набрал команду “!chkimg”. Эта команда сравнивает байты команд в крэшдампе с соответствующими байтами в образе бинарника на диске. Это может быть полезно, например, в случаях аппаратных сбоев RAM или HDD, а также при ошибках патчинга. Я видел случаи, когда до нескольких десятков байт были подвержены изменениям по вышеуказанным причинам. В данном же случае бинарник на диске и выполняемый код из крэшдампа отличались в 9322 байтах.

Возможно, в этом месте, когда выполняемый код бинарника в памяти не совпадает с байтам в образе этого бинарника на диске, слишком чувствительным из вас стоит прекратить чтение. В самом деле — во что дальше вообще верить? Но всё же продолжим!

Теперь мы можем сформулировать проблему ещё более конкретно: почему мы выполняем не тот код, который линкер записал в бинарник?

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

Мой коллега Зак посоветовал мне запускать утилиту sync от sysinternals после окончания работы компоновщика. Я сначала отказался — запуск sync весьма ресурсоёмок и требует прав администратора, но в конце концов я сдался и решил провести этот тест. За выходные я собрал Хром с нуля более 1000 раз, с правами администратора, в трёх разных вариантах:

• Обычная сборка: падает в 3.5% случаев
• 7-секундная пауза после окончания работы линкера: падение в 2% случаев
• Запуск sync.exe после окончания работы линкера: ни единого крэша

Ура! Запуск sync.exe это ещё, конечно, не исправление проблемы (очень уж он ресурсоёмок), но уже кое-что! Следующим шагом стала небольшая программа на С++, которая открывала только что слинкованный бинарник и вызывала для него FlushFileBuffers. Это работало намного быстрее и не требовало прав администратора. И это также предотвращало баг с крэшами для 100% сборок. Финальным шагом стало переписать это на Python, добавить в сборку основной ветки Хрома и написать об этом твит.



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

Я поделился с ним моими находками и методологией исследования. Он с коллегами попробовал воспроизвести баг — но у них не получилось. Возможно потому, что они не запускали сборку Хрома так много раз, как это делал я. Но они помогли мне настроить ETW — инструмент, способный записывать очень детальный лог происходящих в системе событий и останавливать запись в момент ошибки. После нескольких попыток мне удалось воспроизвести баг и записать ETW-лог. Я отправил его ребятам из Microsoft — надеюсь, он поможет им понять проблему.

Проблема была в том, что когда линкер записывает PE-файл (EXE или DLL) используя механизм Memory Mapped File и программа после этого немедленно запускается (или библиотека загружается с помощью вызова LoadLibrary/LoadLibraryEx) и ОС находится в данный момент под большой нагрузкой по вводу/выводу, то вызов flush может завершиться сбоем. Это очень редкое событие, и я могу представить его появление лишь на билд-серверах, вроде моего 24-процессорного монстра при сборке очень больших проектов, типа Хрома. Программисты из Microsoft подтвердили, что моё решение с принудительным Flush после окончания линковки должно помочь исправить проблему (я тоже пришел к этому выводу, поскольку к этому моменту уже получил около 600 последовательных сборок без единого падения) и пообещали внести исправление в ядро Windows.

Если хотите поразбираться сами

Скорее всего у вас не получится воспроизвести данный баг в разумные сроки на своём домашнем компьютере. Я выложил крэшдамп, соответствующие ему бинарник и символьный файл на GitHub. Вы можете загрузить их в Visual Studio и увидеть нули, о которых я говорил выше. Также вы можете загрузить их в WinDbg и воспользоваться командой !chkimg:

0:000> .sympath .
Symbol search path is: .
0:000> .ecxr
eax=cbb75f7e …
re2c!mainCRTStartup:
00412d40 0000  add  byte ptr [eax],al  ds:002b:cbb75f7e=??
0:000> !chkimg
9658 errors : @$ip (00408000-00415815)
0:000> uf eip
re2c+0x12d40:
00412d40 0000  add byte ptr [eax],al
00412d42 0000  add byte ptr [eax],al
00412d44 0000  add byte ptr [eax],al
00412d46 0000  add byte ptr [eax],al

Сложности при исследовании

1) Сборка Хрома заставляет процесс CcmExec.exe терять дескрипторы, что множит зомби-процессы, я написал отдельную статью об этом.

2) Большинство Windows-разработчиков видели число 0xC0000005 достаточно много раз, чтобы запомнить, что оно означает Access Violation. То есть ваша программа обратилась к области памяти, куда ей абсолютно точно не стоило обращаться. Но мало кто может взглянуть на числа 3221225477 или -1073741819 и сказать, что они означают. А на самом деле это то же самое число 0xC0000005 выведенное как знаковое или беззнаковое десятичное целое. Ваш глаз всегда зацепиться за 0xC0000005, но при виде отрицательного числа в пару миллиардов у вас не возникнет ни одной мысли.

3) При исследовании данного бага (crbug.com/644525) был найден и другой (crbug.com/812421). Я волновался, что это один и тот же баг или два взаимосвязанных, но оказалось, что это две совершенно разных истории. Первый баг завершился всем, что описано в данной статье выше, а второй касался Control Flow Guard — защиты от эксплуатации некоторых типов уязвимостей. Оказалось, что при использовании инкрементной линковки и Control Flow Guard иногда возникают проблемы. Простым решением стало обновить наши конфигурации сборки таким образом, чтобы ключи /incremental и /cfg никогда не применялись вместе (это в любом случае имеет мало смысла).

Эпилог

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

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

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

Моё исправление проблемы работает надёжно, для всех комбинаций компиляторов и линкеров. Если вы работаете над программой, которая создаёт исполняемые бинарники, то вам стоит тоже добавить что-то типа вызова FlushFileBuffers перед закрытием файла. (Я, например, отправил внутренний баг разработчикам Go). Проблема на данный момент воспроизводится на всех версиях Windows от 7 до последней 10 со всеми установленными апдейтами, так что позаботьтесь об её исправлении, если это вас касается.