Пошли мы как-то с коллегой на охоту…
Давно я про отладку не писал. Так вот пошли мы как-то с коллегой на Багов охотится. Вышли мы на двух таких матерых, опытных Багов. Их и помотали они нас…
Баг первый.
Захотел мой коллега странного. Хочу, говорит, поддержу USB flash stick на той обрезанной под корень версии Windowы, что мы пользуемся для своих нечеловеческих экспериментов. И не просто поддержку USB stick, но с NTFS на нем. Оказалось, впрочем, что нет ничего проще – достаточно добавить ntfs.sys в образ системы и все должно заработать само собой. Сказано – сделано. Но не работает. Вместо обещанной поддержки, система перестала видеть все USB устройства.
Странно. Коллега сразу же схватился за ружье отладчик и давай копаться в коде PnP. На его беду у него как раз протухли права доступа к исходному коду Windows, а товарищ, ответственный за их раздачу как-то не во время ушел в несознанку. В общем, пока тянулась эта эпопея, процесс отладки несколько усложнился. Тем не менее, через некоторое время коллега добрался до многозначительного сообщения: «Cannot load the configuration file X».
Оказалось, правда, что это просто код пытается вывести юникодную строку с именем файла с помощью ANSI версии printf. «X» был просто первой буквой имени файла. Этот файл был конфигурационный файлом одного из USB устройств. Очевидно, – первым USB устройством, до которого добирался код PnP, после чего все затыкалось. Конфигурационный файл, естественно не менялся со времен царя Гороха. Да и отношения к NTFS никакого не имел.
На следующий день раскопок выяснилось, что вызов ReadFile для чтения этого файла возвращает ошибку ERROR_SECTOR_NOT_FOUND, стоит только добавить ntfs.sys в образ системы. Уже ближе. NTFS, конечно может иметь отношение к ReadFile, однако ntfs.sys даже еще не был загружен в момент возникновения ошибки.
Поиск по исходникам Windows показал, что ошибка ERROR_SECTOR_NOT_FOUND возвращается в случае, если номер сектора превышает общее число секторов на диске. Отследив IRP, коллега выяснил, что драйвер CDFS и драйвер RAM disk не сошлись в оценке размера диска. По версии CDFS диск был на мегабайт больше.
В этот момент пришло озарение. Система грузится из ISO образа, который в процессе загрузки перекладывается на RAM disk для того, чтобы сделать его доступным для записи. Несколькими месяцами ранее мы обрезали размер RAM disk до минимума, чтобы освободить максимум памяти. А размер ntfs.sys – полтора мегабайта. В результате размер ISO получается больше чем может поместиться на RAM disk. А конфигурационный файл случайно оказался в самом конце диска.
Баг второй.
В данный момент я портирую Helios на одну интересную аппаратную платформу. Значительная часть этой работы – адаптация механизма передачи сообщений под эту платформу. И вот в какой-то момент я понимаю, что передача сообщений наконец-то заработала как надо. Осталось доделать пару косметических изменений, которые я откладываю на следующий день. Естественно на следующий день эта пара изменений ломает все к чертовой матери.
Начинаю выяснять что к чему. По симптомам похоже, что пакет портится при передаче. Включаю режим “DMA paranoia”, т.е. режим вычисления и проверки контрольных сумм при передаче. Там в коде забавный комментарий, кстати:
Optional DMA Paranoia, because we had an offset wrong once…
Опциональная DMA паранойя, так как мы однажды уже посчитали смещение неправильно…
Параноидальная проверка подтверждает – пакет портится. Не понятно, правда, почему.
Добавляю вывод отладочной информации, показывающий состояние очереди и первые 16 байт пакетов при передаче и приеме. Ясности это не добавляет. Все выглядит прилично. Указатели пересчитываются именно так как должны. Данные передаются правильно. Повторяю эту процедуру несколько раз: добавляю больше отладочного вывода, медитирую, убеждаюсь что все работает как и должно, но пакеты портятся.
Наконец замечаю, что порча пакетов происходит прямо во время приема очередного пакета. Т.е. сначала я вижу строчку о том, что пакет с такими-то полями получен, а потом я вижу сообщение об испорченном пакете, которое выводит следующий метод, обрабатывающий этот же пакет. «Наверное это потому, что данные пакета пишутся в память асинхронно», – думает голодный мозг по дороге на обед. «Фиг вам, там все синхронизировано в нужных местах», – отвечает сытый мозг по дороге с обеда.
Наверное, это указатели пересчитываются неправильно. Разные ядра видят куски сообщений по разным адресам. При передаче эту указатели пересчитываются. Вывожу все указатели в лог, но указатели пересчитываются правильно.
Но кто же, все-таки, переписывает данные? Фильтрую все операции копирования памяти из логов и загружаю в Excel чтобы посмотреть нет ли перекрытия. Есть перекрытие! Похоже, что ошибка кроется где-то в районе обработки wrap around, – там где указатели переходят из начала очереди в конец.
Загружаю историю состояний указателей очереди в Excel и вижу, что одно из восьми ядер показывает аномальное значение указателя начала очереди, которое нарушает монотонность ряда. Значение правильно выровнено, – значит это ошибка в вычислении указателей очереди. Реконструирую историю значениё этого указателя по всем восьми ядрам. Получается, что это значение туда никто не писал.
Я очень редко ухожу с работы позднее 5-ти. Не смотря на ZBB, дедлайны и проч. В этот раз я задержался до семи вечера. Но недаром говорят, что утро вечера мудренее. Следующим утром, надевая носки на лестнице (извините за подробности), прихожу к выводу, что это больше похоже на аппаратную проблему. Проверить это очень просто, достаточно завести две копии каждого указателя и проверять их на совпадение. Делаю пробный запуск и точно – чтение указателя из памяти иногда возвращает неверное значение.
А дальше был интересный разговор с производителем железки и прочие скучные подробности.
Ну, тут можно добавить, что загрузить систему с usb флэшки (xp, 2003) со штатными usb драйверами нереально (в штатных драйверах просто неверный код инициализации в boot режиме), нужно брать драйверы от xp embedded.
Чисто из природной вредности замечу, что XP/2003 вышли 7 лет назад.
Меня больше прикалывают “квантовые баги” ака “баги Гейзенберга” – попытка пронаблюдать их под отладчиком вызывает их моментальное исчезновение. Отладчик выключается, баги тут же возвращаются
И не такое бывает. Скажем достаточно посмотреть отладчиком на память и труба.
Второй баг – хардкорный
@Алексей Пахунов
Но в новых то версиях засилие C# повсеместно и прочих подобных технологий, а те системы C/C++ (видимо последние).
Подскажите, каким образом можно смотреть в экселе логи и их визуализацию?
Не читайте советских газет.
Попробуйте открыть текстовый файл в Excel-е. Он предложит указать формат файла: чем колонки разделяются и т.п. Достаточно, чтобы логи (или интересующий вас кусок лога) имели регуляроную структуру. А дальше Excel много чего умеет делать с табличными данными.
скажите почему (исправлено) мс перестал winmobile поддерживать? там такие же баги?
Следите за языком, пожалуйста. В следующий раз забаню нафиг. :-/
На счет WinMobile – без понятия. Я за мобильным рынком вообще не слежу.
Баги к прекращению поддержки продукта вообще отношения не могут иметь. К (не) выпуску продукта – могут. К прекращению поддержки – нет.
Так я их и не читаю, я драйверы пишу под эти системы (ну и соответственно все отличия вижу, в виду того, что установлена вся линейка систем).
Ну я вот запустил Process Explorer. Он говорит, что у меня на машине запущен 1 (один) .NET процесс. А именно, одна из служб, установленных нашим IT, которая в стандартную поставку не входит. Засилье .NET во всей красе.
Запустите mmc или нажмите manage на my computer (в vista или win7) (а также все менеджеры инсталляции и т.п. написаны на .net). Более того в ядре еще заглушен вывод отладочных строу из юзермода (на win7), а если это пропатчить – то из mmc будут валиться в отладчик тысячи строк логов (и из прочих программ входящих в состав win7). (Заглушка сделала двух уровневая, в kernel32 и в ядре, поэтому даже вывод отладочных строк через ntdll на win7 не работает, сделали это для борьбы с нерадивыми программистами, которые в release версиях не убирают отладочный вывод).
Эк вам .NET досадил. Вместе с mmc получается два процесса. Из восьмидесяти.
Дык если nt!Kd_WIN2000_Mask пропатчить (и заодно – остальные nt!Kd_Xxx_Mask) посыпяться тысячи сообщений от драйверов.
А вы попробуйте для эксперимента вообще .net полностью удалить из win7 (боюсь система даже не загрузится), а win2003 работает при этом без проблем (там .net для работы системы не нужен).
Ну и более того в win7 всякие xml парсеры (c++ ные) даже в загрузчике системы!
С драйверами проблем нету, проблема только что OutputDebugString не работает (в msdn об этом ни слова не сказано).
Да загрузится, куда она денется? Естественно, все утилиты завязанные на .NET накроются после такого обрезания. Ну и что? Я в упор не вижу проблемы от наличия и использования .NET в системе. Кроме того, что вам, похоже, он сильно не нравится.
Не вижу принципиальной разницы между парсером XML и парсером INI файлов в загрузчике.
Оно?
Плюс целая статья про “Reading and Filtering Debugging Messages”.
Нет – не оно, отдизасемблируйте OutputDebugString на win7, там просто стоит ret.
А чтобы послать текст в отладчик через ntdll нужно пропатчить ядро, т.к. в ядре есть проверка и если PreviousMode != KernelMode – то вывод игнорируется не зависимо от фильтров. Хотя вы все это можете посомтреть в исходниках (если туда доступ есть).
Дизассемблировал. Там не ret. Там код бросающий специальное исключение для отладчика.
Я проследил весь путь в исходниках. Я думаю что я куда-то не туда смотрю. Единственная проверка “PreviousMode != KernelMode” там используется для того, чтобы сделать ProbeForRead. Фильтрация там идет совсем по другим критериям. Назовите конкретное место, что б отладчиком посмотрел.
Ну, вот фрагменты дизасма:
kernel32.dll (сразу редирект на api-ms-win-core-debug-l1-1-0.dll)
.text:77E21607 ; void __stdcall OutputDebugStringA(LPCSTR lpOutputString)
.text:77E21607 _OutputDebugStringA@4 proc near ; CODE XREF: OutputDebugStringAStub(x)+6j
.text:77E21607 ; DbgPrintOut(_DPF_LEVEL,char const *,…)+27p
.text:77E21607 ; DbgPrintOut(_DPF_LEVEL,char const *,…):loc_77E42859p
.text:77E21607 ; DbgPrintOut(_DPF_LEVEL,char const *,…)+59p
.text:77E21607
.text:77E21607 lpOutputString = dword ptr 4
.text:77E21607
.text:77E21607 jmp ds:__imp__OutputDebugStringA@4 ; OutputDebugStringA(x)
.text:77E21607 _OutputDebugStringA@4 endp
Далее (api-ms-win-core-debug-l1-1-0.dll):
.text:11C01068 ; Exported entry 3. OutputDebugStringA
.text:11C01068 ; Exported entry 4. OutputDebugStringW
.text:11C01068
.text:11C01068 ; =============== S U B R O U T I N E =======================================
.text:11C01068
.text:11C01068
.text:11C01068 ; void __stdcall OutputDebugStringW(LPCWSTR lpOutputString)
.text:11C01068 public _OutputDebugStringW@4
.text:11C01068 _OutputDebugStringW@4 proc near
.text:11C01068
.text:11C01068 lpOutputString = dword ptr 4
.text:11C01068
.text:11C01068 retn 4 ; OutputDebugStringA
.text:11C01068 _OutputDebugStringW@4 endp
P.S. win7 (7100) в 7600 возможно и вернули как было в vista (надо посмотреть).
Чего-то я не понял, по поводу первого бага, почему при копировании ошибка была не – нехватка места на рам-диске?
ну и вообще, чтобы ro сделать rw с помощью рам-диска, есть aufs
Собственно проблема даже не в ядре (я уже подзабыл), а в ntdll.dll
см. функцию vDbgPrintExWithPrefixInternal.
Там есть условие:
if ( CompId != -1
&& (!Teb->Peb->BeingDebugged || CompId != 101)
&& !ZwQueryDebugFilterState(CompId, Level)
|| (v8 = *(_WORD *)(v6 + 4042), v8 & 2) )
return 0;
Ключевой момент – Teb->Peb->BeingDebugged, для отладчика ядра это всегда false (т.к. он ни к каким процессам не подключается). Соответственно и вывод в него не работает. Вывод может работать только в отладчик который делает подключение к Debug порту процесса.
Все api-ms-*.dll не содержат кода, только заглушки. Они нужны, чтобы утилиты вроде depends с ума не сходили. Загрузчик перенаправляет все подобные ссылки на библиотеки, которые на самом деле экпортируют ту или иную функцию. В данном случае управление передается на kernelbase!OutputDebugStringA со вполне полной реализацией OutputDebugString. Это хвосты apiset.
Ключевой момент – это на самом деле вызов !ZwQueryDebugFilterState(CompId, Level). Эта функция и реализует фильтрацию сообщений о которой я говорил выше. И которая описана в MSDN.
В отсутствие user mode отладчика OutputDebugString вызовет DbgPrint, чтобы передать строку в kernel mode отладчик. DbgPrint вызывает vDbgPrintExWithPrefixInternal с CompId == DPFLTR_DEFAULT_ID (101). vDbgPrintExWithPrefixInternal вызовет ZwQueryDebugFilterState, так как BeingDebugged == FALSE, а CompId == DPFLTR_DEFAULT_ID. А дальше ZwQueryDebugFilterState решает, пропускать сообщение или нет.
Вот статья в MSDN про которую я говорил: Reading and Filtering Debugging Messages.
Драйвер фаловой системы запрашивал сектор за пределами RAM disk. Ошибка была не “нехватка места”, а “сектор не найден”.
Даже если функцию NtQueryDebugFilterState в ядре пропатчить чтобы она всегда возвращала true, то простейшая usermode программа, приведенная ниже, ничего не выдаст в отладчик ядра. А выдаст только если пропатчено условие в ntdll.dll (при непропатченом ntdll до DbgPrint в ядре даже дело не доходит).
#include
int main()
{
OutputDebugString(“Hello world!\n”);
return 0;
}
Не нужно патчить код. Нужно патчить специальные заведенное для этого переменные – так, как велит MSDN:
Да маска эта задана через реестр, Session Manager\Debug Filter\WIN2000 (или както так), это можно в коде инициализации ядра посомтерть, там здоровенный массив этих масок их значения из реестра читаются, в маске этой у меня 0xFFFFFFFF прописано.
Ну и к томуже при каждой загрузке менять маску руками – все равно накладно. А вот невозможность включить режим совместимости с предыдущими версиями – это существенный прощет. В vista было достаточно всего DEFAULTFILTER задать (в реестре) и вывод работал везде, также как в nt4 и в w2k.
HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Session Manager\Debug Print Filter
Вы меня потеряли…
Установить маску WIN2000 в 0xf – это и есть режим совместимости. Установить её можно и в отладчике и в реестре. Кусок лога отладчика при первом способе я показал выше. Хотите второй – пожалуйста:
Отладчик локальный или через kdxxx драйвер? (kdcom, kd1394 и т.п.) Я проверял через отладчик по кабелю (не через local kd). Может конечно маску неправилно прописал в реестр, но путь к маске брал из кода инициализации ядра, где эти маски все из реетсра читаются.
Да без разницы. Способ подключение отладчика тут побоку. Главное чтобы это был ядерный отладчик. Я подключался по com порту в данном случае.
Скорее всего. В MSDN прописан правильный путь. В ядре, конечно, тоже. Но из ядра его все-таки сложнее выковырять, чем из MSDN.
Это я понял. Почему ошибка не возникла на этапе копирования диска в рам-диск?
Потому что на RAM disk ничего не копировалось. RAM disk создавался на месте уже загруженного в память ISO. Банально драйвер получал указатель и размер ISO. Последний был константой, а не брался из самого ISO.
Проблема оказалась вот в этой проверке (vDbgPrintExWithPrefixInternal из ntdll.dll):
call _RtlpIsKernelDebuggerActive@0 ; RtlpIsKernelDebuggerActive()
test al, al
jz short DebuggerNotActive
Эта функция всегда возвращает 0 (у меня раньше тут тоже пропатчено было).
Маски у меня естественно все правильно были прописаны.
Почему эта функция возвращает 0 – непонятно, дебагер подключен и активен, более того прекрасно работает.
В переменной котоаря проверяется внутри _RtlpIsKernelDebuggerActive (001b:76e92df6 a0d402fe7f mov al,byte ptr [SharedUserData+0x2d4 (7ffe02d4)]) лежит 1, а проверяется 2 младших бита на значение 3.
Похоже, что отладчик постоянно теряет связь. Когда приходит команда с клавиатуры, он заново инициализирует соединение, потом обменивается пакетами с ядром, а затем снова теряет связь. Как только это происходит 3 (есть контакт) сбрасывается в 1 (отладчик разрешен в bcd).
Вы на всякий случай кабель проверьте. А еще лучше попробуйте другой тип подключения. У меня как-то проблемы с совместимостью FireWire карт были, к примеру. Может поможет.
Это транспорт virtualkd (kdvm.dll) для отладки под vmware. Возможно в нем просто не совсем правильно реализован протокол обмена. Поскольку virtualkd в исходниках, можно посмотреть и поправить.
А вообще конечно странно, почему вывод строк из kernel mode работает без проблемы, а проблемы только с выводом из user mode?
Маска WIN2000 оказалась вообще не нужна, при ее установке в отладчик сыплется мусор от все системных компонент (в основном манифесты от лоадера). Достаточно заданной маски DEFAULT (как в vista).
Видимо так.
В том месте строка может передана либо (в порядке приоритета):
1. user mode отладчик
2. kernel mode отладчик
3. vectored exception handler.
Зачем нужен #3 – не знаю. Когда строка выводится в ядре, то этого выбора нет и она всегда отправляется в kernel mode отладчик.
Ну раз тут такая большая тема об отладке и багах получилась приведу еще один пример:
В любой версии msvc (от 6 до 2010) скомпилировать и запустить следующий пример:
int main()
{
_ASSERTE(1%sizof(char)==1);
return 0;
}
(Компилировать в отладочном режиме, пробелы в строке с ASSRTE не ставить).
При запуске программа вылетит в коде xxxprintxxx т.к. туда будет передана форматная строка %s без параметра (баг в заголовочном файле crt). Я даже тикет такой создал на сайте микрософта по msvc (но тикет был сразуже закрыт, со ссылкой на то что у нас по плану выпуск msvc 2010 и баг этот мы исправлять не будем).
В msdn кстати в описанни printf и прочих написано черным по белому, никогда не передавать в качестве форматной строки произвольные строки, а делать “%s” или “%ls” и строку передавать в качестве аргумента.
Тикет пока что найти не смог (забыл в каком месте его создавал, гдето через microsoft connect).
А собственно вот, нашел ссылку
http://connect.microsoft.com/VisualStudio/feedback/details/475018/bug-in-assert-expr-macro-definition
Вон, ктото еще поиском пользоваться не умеет и создал повторный тикет
http://connect.microsoft.com/VisualStudio/feedback/details/558739/c-c-cannot-use-mod-operator-in-asserte-causes-stack-clobber
Посмотрел отличия kdvm и kdcom(от win7). В kdcom используются 2 глобальные переменные:
в одном месте
LOBYTE(KdDebuggerNotPresent) = 0;
vffdf02d4 |= 2u;
в другом месте
LOBYTE(KdDebuggerNotPresent) = 1;
vffdf02d4 &= 0xFDu;
В kdvm используется только экспортируемая переменная KdDebuggerNotPresent.
vffdf02d4 – это видимо то, что отображается в юзермод на адрес 7ffe02d4 (в SharedUserData)
SQL injection в чистом виде.
Да, это оно.