highly professional scums

При отладке этого бага в какой-то момент времени у меня даже появилась уверенность, что я имею дело с багом компилятора, а не с программистской ошибкой. Тем не менее, бага была найдена, работоспособность программы в Release конфигурации восстановлена, а репутация компилятора MSVC осталась {пока что} “непокобелимой”.

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

char column1[256];

char column2[256];

char column3[256];

char column4[256];

...

sqlDiver.Bind(1, column1, sizeof(column1));

sqlDiver.Bind(2, column2, sizeof(column2));

sqlDiver.Bind(3, column3, sizeof(column3));

sqlDiver.Bind(4, column4, sizeof(column4));while (sqlDiver.MoveNext())

{

    if (stage == NONE)

    {

        ... Анализируем column1 и заполняем stage правильно

    }

    else if (stage == STAGE_PROCESS_INFO1)

    {

        ... Кидаем данные из column2...4 в списки

    }

    else if (stage == STAGE_PROCESS_INFO2)

    {

        ... Кидаем данные из column2...4 в списки

    }

    else ...

}

Проблема была в том, что код в дебаге работал нормально, в релизе – нет. Кстати, при просмотре в коде уже были обнаружены разные дополнительные строчки со страшными комментариями, что вставлены они только для того, чтобы все в Release заработало. Действительно работало, но недолго :(.
Изначально оказалось, что поведение системы в Release заключалось в следующем: никакие списки INFO1, INFO2 и другие не заполнялись вообще. Поэтому после считывания данных из SQL таблицы системы рапортовала, что не может найти никаких данных для анализа, и успокаивалась. В Debug при этом все работало правильно.

Вполне естественное желание в этой ситуации – это заглянуть в дизассемблер и посмотреть, где мы там гуляем. Код, разумеется, оптимизированный до безобразия, но по вызовам ключевых функций можно было догадаться, что ни в один if() мы не попадаем. После более тщательного анализа было найдено, что переменная stage лежит на стеке, а вот оптимизатор в самом начале функции решил записать ноль в переменную ESI и сравнивать с ней. Так что получилось примерно следующее:

_ESI = 0;

...

char column1[256];

...

if (stage == _ESI)

    {

        ... Анализируем column1 и заполняем stage правильно

...

Выяснилось, что _ESI к моменту выполнения первого if() содержит не 0, а 0xFFFFFFFF, и соответственно, никакое из условий не выполняется. Также быстро выяснилось, что значение ESI меняется в процессе вызова sqlDiver.MoveNext().

Лирическое отступление. Компилятор, разумеется, сохраняет значение основных регистров в процессе вызова функций. Для этого используется стек примерно следующим образом:

bool SqlDiver::MoveNext()

{

0090B430  push        ebp

0090B431  mov         ebp,esp

0090B433  push        0FFFFFFFFh

0090B435  push        offset __ehhandler$?MoveNext@SqlDiver@easyodbc@@QAE_NXZ (0C3FC40h)

0090B43A  mov         eax,dword ptr fs:[00000000h]

0090B440  push        eax

0090B441  push        ecx

0090B442  sub         esp,0D8h

0090B448  push        ebx

0090B449  push        esi

0090B44A  push        edi

0090B44B  push        ecx

...

0090B489  call        @ILT+42070(_SQLFetchScroll@12) (6D845Bh)

...

0090B4DA  pop         ecx

0090B4DB  pop         edi

0090B4DC  pop         esi

0090B4DD  pop         ebx

0090B4DE  add         esp,0E8h

0090B4E4  cmp         ebp,esp

0090B4E6  call        @ILT+88040(__RTC_CheckEsp) (6E37EDh)

0090B4EB  mov         esp,ebp

0090B4ED  pop         ebp

0090B4EE  ret

Весь код внушал здоровый оптимизм, но тем не менее, вызов pop esi получал 0xFFFFFFFF вместо ожидаемого нуля. Вызов внутренней функции SQLFetchScroll() вместе с одновременным просмотром содержимого Memory 1 действительно показывал, что в том месте, где было сохранено значение ESI, появлялось 0xFFFFFFFF. Data Breakpoint показал, что по указанному адресу трижды происходило сохранение “левых” данных.

0x0012291E  12 00 00 00 00 00 01 00 00 00 3c 2a  ..........<*

0x0012292A  ff ff ff ff 90 00 01 00 00 00 a4 26  ...........&

0x00122936  8c 02 d1 1e 38 f4 e0 33 12 00 00 34  ..С.8фа3...4

Начиная с этого момента основная концентрация сил произошла вокруг вызова SQLFetchScroll(). Имело место быть гипотеза, что неправильная комбинация аргументов приводила к тому, что затирался стек. Однако затирка была очень странная – происходило затирание четырех байтов стека выше функции вызова – это совсем не было похоже ни на buffer overrun, ни на другие проявления ошибок памяти. Целенаправленно терлись именно 4 байта посередине стекфрейма. Кроме того, гугль про ошибки на стеке при вызове SQLFetchScroll() молчал как партизан.

Чтобы было понятнее, подробнее расскажу, что делалось. Метод Bind() связывал информацию из столбцов с указанными переменными column1…4, метод MoveNext() считывал следующую строчку из SQL таблицы и распихивал данные по указанным ранее переменным (особо сложных аргументов у него не было). Метод Bind() выглядел примерно так:

bool SqlDiver::Bind(int col_no, char* buff, int len)

{

    SQLINTEGER sz = 0;

    SQLRETURN rc = SQLBindCol(m_hStmt, col_no, SQL_C_CHAR, buff, len, &sz);

    if (rc == SQL_ERROR)

    {

        HandleError();

    }

    ...

}

Бага не поддавалась. Было перепробовано несколько вариантов, добавлялось отладочное протоколирование системы (поскольку после прохода по дизассмблеру было предположение, что в Bind() передаются некорректные адреса column1…4), отключалось whole program optimization (так как линковка приложения занимала непозволительно долгое время). Все эти изыскания приводили либо к тому, что бага пропадала, либо к тому, что программа зависала (внутри NTDLL!), либо к тому, что падение начинало происходить в совсем неожиданных местах. Ключевым моментом в понимании процессов стало то, что я попробовал увеличить размеры column1…4 в несколько раз, сохранив размеры передаваемых аргументов как 256 байт. Ошибка осталась на том же месте, и это стало основой для понимания того, что с буферами никаких проблем нет. Также никаких изменений в поведении программы не было при переносе colunm1…4 в статическую область памяти.

Отчаявшись найти ошибку таким образом, я таки решил “прочитать инструкцию” и посмотреть, что из себя представляют SQL методы SQLBindCol и SQLFetchScroll. Озарение пришло в момент просмотра туториала – в туториале последний аргумент SQLBindCol() ссылался на глобальную область памяти. Мгновенно стало ясно, что buff и sz должны быть глобальными переменными, адреса которых ЗАПОМИНАЮТСЯ в SQLBindCol() и ЗАПОЛНЯЮТСЯ при вызове SQLFetchScroll(). В нашем случае ацйкий инди-код от стороннего туториала передавал в SQLBindCol() адрес ЛОКАЛЬНОЙ переменной sz, которая теряла всякую осмысленность после возврата из метода Bind. При последующем вызове MoveNext() по этому адресу оказывалось значение сохраненной переменной ESI, куда и записывалось -1 или 0xFFFFFFFF. После возврата из MoveNext() поведение программы зависело от фазы луны.

Ошибка была исправлена после переноса переменной SQLINTEGER sz в статическую область памяти. Суммарный дебаг занял около двух часов.

Выводы из дебага:
1. Нам сильно повезло, что изначальное проявление ошибки было именно в области ее возникновения. Если бы изначально ошибка проявлялась в зависании в NTDLL, на поиск можно было бы потратить сильно больше двух часов. Пример такой отладки я приводил ранее, в статье “Рецепты отладки. Четырехмесячный дебаг.”.
2. Несмотря на то, что симптомы ошибки очень напоминали сбой компилятора, в ошибке все равно надо было разобраться подробно. Когда-нибудь, когда я натолкнусь на действительный баг компилятора, я опишу последовательность событий. В данном случае попытка однозначной классификации как баг компилятора или как баг программиста дала положительный (для компилятора, разумеется :)), ответ.
3. Ошибка возникала и ранее, в коде были видны попытки добавить stub-вызовы таким образом, чтобы исключить эффект от затирания ESI. Хорошо, что ошибка стала проявляться снова еще в период разработки ПО, а не у заказчика (или, например, стала бы проявляться после защиты старфорсом).
4. Ошибка могла и не проявиться вообще. Например, если бы компилятор не стал бы оптимизировать работу с ESI или если бы вызов SQLFetchScroll() не отработал бы на базе данных ни разу. Тем не менее, ошибка присутствовала в коде, и только у-порно-дебаг позволил ее найти и исключить.
5. Читайте документацию и изучайте туториалы. Они вам могут понять, как надо использовать функции (а не как вы их хотите использовать).
6. Несанкционированное изменение значений переменных и регистров – часто результат работы с локальными переменными предыдущих функций. Это может либо возврат адреса локальной переменной в вызывающую функцию, либо (как в этом экзотическом случае) сохранение адреса локальной переменной для последующей работы.
7. Внешние семплы и врапперы – не всегда в помощь ))))

Какие конкретно приемы были использованы для поиска бага:
1. Анализ дизассемблера сбойной функции для понимания того, какие изменения в регистрах произошли и того, что они произошли несанкционированно для компилятора/оптимизатора;
2. Анализ дизассемблера вызываемой функции, чтобы исключить ошибки компилятора внутри MoveNext();
3. Memory Watch и Data breakpoint для проверки несанкционированного изменения стека;
4. Изменение настроек компилятора и параметров функций для попыток вывести ошибку в другую область памяти;

Ключевым приемом стало, впрочем, именно прочтение документации ))))).

Приятной вам отладки.