Баг компилятора? Линкера? Нет, баг ядра Windows

https://randomascii.wordpress.com/2018/02/25/compiler-bug-linker-bug-windows-kernel-bug/
  • Перевод
imageГейзенбаг — это худшее, что может произойти. В описанном ниже исследовании, которое растянулось на 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, добавить в сборку основной ветки Хрома и написать об этом твит.

image

Позже в этот же день (я даже не успел отправить официальный багрепорт в 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 со всеми установленными апдейтами, так что позаботьтесь об её исправлении, если это вас касается.
Инфопульс Украина 175,56
Creating Value, Delivering Excellence
Поделиться публикацией
Комментарии 32
  • +4

    Напомнило баг из собственной практики… Довольно большой проект (около получаса полной сборки) собирался под виндой цигвином. Собирался на самом деле с помощью visual studio, но с помощью make от cygwin, а потому в его среде (не я это придумал). И вот если был запущен файрфокс, а в нем были открыты пара страничек с видео (тогда еще в flash), то в какой-то момент cygwin начинал валиться в coredump. Стоило перезапустить файрвокс и сборка опять налаживалась. Вот такие чудеса бывают.

    • +6
      Это совсем другая история. CygWin пытается эмулировать fork — и сделано это через такое место, что высказывание Роланда (сказанное им по похожему, но другому поводу) оказывается весьма к месту: «если говорить начистоту, то сравнивать этот подход со скотчем, алюминиевой проволокой или жевательной резинкой — это оскорбление всех трёх преотличных строительных материалов» (Frankly, I think referring to this scheme with «duct tape», «bailing wire», or «chewing gum» does a disservice to all three of those fine building materials.)

      Там и не только Firefox мог повлиять…
      • +1
        Судя по всему, оно даже в исполнении MS магически сделано:
        As a final example, the Linux fork syscall has no documented equivalent for Windows. When a fork syscall is made on WSL, lxss.sys does some of the initial work to prepare for copying the process. It then calls internal NT APIs to create the process with the correct semantics and create a thread in the process with an identical register context. Finally, it does some additional work to complete copying the process and resumes the new process so it can begin executing.

        Прям даже интересно стало, как это в Cygwin реализовали.
        • +2
          Нашел. Люто, однако.
          Parent initializes a space in the Cygwin process table for child. Parent creates child suspended using Win32 CreateProcess call, giving the same path it was invoked with itself. Parent calls setjmp to save its own context and then sets a pointer to this in the Cygwin shared memory area (shared among all Cygwin tasks). Parent fills in the child's .data and .bss subsections by copying from its own address space into the suspended child's address space. Parent then starts the child. Parent waits on mutex for child to get to safe point. Child starts and discovers if has been forked and then longjumps using the saved jump buffer. Child sets mutex parent is waiting on and then blocks on another mutex waiting for parent to fill in its stack and heap. Parent notices child is in safe area, copies stack and heap from itself into child, releases the mutex the child is waiting on and returns from the fork call. Child wakes from blocking on mutex, recreates any mmapped areas passed to it via shared area and then returns from fork itself.

          И всему этому мешает рандомизация адресного пространства (ASLR), отсутствие адресо-незаависимого кода (PIC) в Win, и другие радости.
        • –1
          bailing wire — упаковочная проволока, обвязочная проволока, не «алюминиевая проволока».
          bailing wire — Small rolls of soft iron wire
          Откуда взялся алюминий? Алюминиевая проволока — ломкая, и её обычно сдают во вторсырьё.
          • 0
            Скорее всего имеется ввиду алюминиевая проволока получаемая из старых уличных проводов, которая в советские и несколько позже времена была весьма ходовым крепёжным материалом. Да и сейчас встречается, если удаётся найти провода (сейчас их сразу сдают обычно, так что найти почти нереально)
            • +4
              Что-то мне подсказывает, что не стоит пытаться дословно переводить англоязычные аналоги выражения «из говна и палок», тогда нашему «примотай проволокой» (конечно-же алюминейвой, толщиной в 1,5-2 мм, которая была в каждой квартире) оно очень даже хорошо будет соответствовать.
            • +4
              Если это высказывание несколько локализовать, то можно сказать, что говно и палки — отличный стройматериал.
              • +2
                А если облагородить, то спички и жёлуди.
          • 0
            Напомнило хайку про ошибки:
            Three things are certain:
            Death, taxes, and lost data.
            Guess which has occurred.
            ©

            • +1
              ©

              Но ведь…
              The Free Software Foundation claims no copyright on this joke.
            • +2
              У меня была чем-то похожая история. Настроил на телефоне с Sailfish OS по расписанию запуск скрипта, который выкачивал обновления большого файла в zip архиве. При запуске руками скрипт отрабатывал отлично, а вот при работе по расписанию unzip в большинстве случаев создавал битый файл, в котором был тупо пропущен кусок. Ровно 64 KiB. Не в хвосте или начале, а в случайном месте! Очень удивительно было искать причины.
              • +4

                Это ещё что, я баг в прошивке винчестера находил.

                • 0
                  Баги в винтах, похоже, обычное дело. У меня есть диск (Samsung), который при записи пропускает серию из 69 блоков — всегда в разных местах. Просто не пишет их на блины, оставляя там старые данные посреди новых.
              • +1
                я мог (при сопутствующей удаче) собирать Хром до 12 раз в час

                взгрустнулось, когда вспомнил сколько компилировался хром на моем ноутбуке.
                • 0
                  64 с нуля собирается за пару часов на обычном i7. Ребята там серьёзно потрудились над сборкой. А у этого чувака из гугла так вообще goma — распределённая система компиляции хрома. Так что там у него только линковка финальная и осталась небось.
                  • 0
                    У меня на i5 собиралась часов 4-5.
                    Как у него собирается я не понял. У него 24 ядра и 64 памяти на рабочей машине для тестов сборки. Хотя он действительно писал, что использует распределенную компиляцию.
                    Все равно, лишний раз напомнил мне, что пора обновляться.
                    • 0
                      Это старые так долго были. У меня домашний i5 не больше собирает. Там они придумали джамбо билды — это сильно уменьшает необходимое время.
                      • 0
                        Может быть, не знаю. Это полтора-два года назад было. Я дженту использовал, и поскольку это не имело отношение к работе, повышение энторопии вселенной меня довольно быстро утомило. Особенно, когда сваливались апдейты хромиума, лвм и т.д., раздражало.
                  • 0
                    Всё упирается в генерацию объетков. А линковка может быть и на клиенте. Если кофиги компиляторов везде одинаковые, то почему нет.
                  • 0
                    напомнило баг с akka (до актора просто не доходили сообщения при async вызове) под .net который воспроизводился только на intel ix-3xxx серии.
                    Только мы так и не поняли в чём проблема, не было времени разбираться учитывая что сервера были на зеонах 4 поколения а не 3 :)
                    • +3
                      Обычные админские будни (что не делает их менее увлекательными). Basic assumptions are wrong. И обычно процесс дебага проходит где-то по грани между «how much you'd dare» и «don't be silly». Предполагать, что базовые инструменты сломаны — дерзко. Утверждать, что x86_64 переключился в режим z80 глупо. Вот где-то тут обычно тяжкие баги и луркают.
                      • 0
                        думаю, что корень проблемы в новых патчах Windows. те которые должны были закрыть серьезные «новогодние» уязвимости. плюс к этому стоит добавить 24 ядерный процессор на котором с большой вероятностью не оттестированы данные патчи. также стоит упомянуть, что основные тормоза после применения патча возникают именно на дисковых операциях. возможно патч написал с очередными «компромиссами». много разных «возможно», но попробуйте покопать в эту сторону. например часть патчей исключить из windows и запустить компиляцию. сам имею 2x 10 ядерника и поэтому интересно будет увидеть решение.
                        • +4
                          Вы это серьёзно? Новогодние патчи настолько круты, что меняют кривизну пространства в районе сервера и заставляют сервер работать неправильно в прошлом?

                          Это фантастика какая-то. Только непонятно как тут что-либо тестировать: если патчи настолько круты, что влияют не прошлое, то уж на поведение в будущем, после их удаления, они и подавно будут влиять…
                          • –1
                            У меня была такая мысль, но я решил оставить сообщение и ждал данного замечания. Но автор два года бьется с несколькими багами и не знает с чем именно имеет дело. Кроме того автор может немного приумножить время по объему затраченного труда…

                            Если для вас это фантастика, то вы явно далеки от реальности. Ядро виндовс достаточно стабильное, но при этом имеет баги. Автор именно их и копает за что ему огромное спасибо. Почитайте его темы.
                            • +2
                              Если для вас это фантастика, то вы явно далеки от реальности.
                              Да, для нас звучит фантастикой, что новогодние патчи 2018 года могли улететь в прошное и вызвать баги в 2016-м году. Вы твёрдо уверены, что это именно мы далеки от реальности?
                        • +1
                          На такой машине, наверняка, есть RAID контроллер, у которого есть Кеш, который используется до записи данных на диск.
                          И я думаю проблема скорее в нем, чем в ОС.
                          Иначе с багом столкнулись бы намного раньше. Вы же не думаете, что только в гугле запускают Файлы сразу после сборки на высокозагруженных машинах?
                          • +1
                            На такой машине нет никакого RAID'а ибо смысла в нём — нуль: если это билд-сервер, то на нём по определению ничего особо важного не хранится.
                        • +2

                          Есть по этому поводу известная цитата, довольно известного разработчика. Там правда не про Windows, но любопытно.


                          I’m always ready to suspect gcc since it has been a cause of so much trouble in the past.
                          — Ron Minnich, main author of CoreBoot and LinuxBIOS.
                          • –4
                            Может у него на компьютере используется RAM-disk который имеет баги эмуляции диска.
                            • 0
                              Ну и комменты, хорошо, что перевод!

                              Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

                              Самое читаемое