Не устанавливаются приложения, тормозит станция

Сегодня я хотел бы обсудить довольно специфическую проблему, которая долгое время не давала покоя техническому отделу, скажем так условного корпоративного клиента. Не то что бы она была какой-то уж чрезвычайно сложной, скорее просто никому не интересной (как в том анекдоте про Джо), и решалась местным персоналом при помощи полной "перезаливки" станции пользователя. Кстати, к слову сказать, проблема, которая будет описана в данной статье, мне уже встречалась, но всё никак не появлялось возможности обстоятельного её изучения. Благо, не так давно возникший аналогичный инцидент явился отправной точкой для написания этой заметки. Надо заметить, что для детального описания сбоев, в будущем хотелось бы все же разработать какой-нибудь единый диагностический шаблон, то есть собрать с проблемной станции именно ту информацию, которая представляла бы собой наиболее точное описание всех необходимых конфигураций и однозначно идентифицировала проблему, что бы пользователи могли находить решения по проблемам со схожими симптомам.

Описание проблемы

Рабочее окружение:

• Корпоративная доменная среда;
• Пользовательская станция под управлением Windows 7 Professional x64 6.1.7601 SP1;
• Агент SCCM 2012 версия 5.00.8239.1403.

Иногда (на самом деле редко) при введении в эксплуатацию свежеперезалитой/сохранившейся от другого пользователя рабочей станции, счастливый обладатель начинал жаловался на чрезвычайно низкую работоспособность: многие программы запускались крайне медленно (на протяжении десятков минут!). Работать же в уже запущенных приложениях было совершенно невозможно. При удаленном подключении к станции и попытке удалить произвольное программное обеспечение, было зафиксировано, что процессы инсталляций/деинсталляций "виснут", то есть сам процесс установки/удаления может длиться бесконечно, не завершаясь в течении приемлемого временного интервала. Когда удавалось запустить какое-либо диагностическое ПО (Process Hacker / Process Explorer и подобные), была зафиксирована активность с базой (хранилищем) компонентов. Кроме этого никаких отличительных симптомов обнаружить не удалось.

Диагностика

Убедившись в том, что пользовательская станция действительно ОЧЕНЬ СИЛЬНО тормозит, я решил не прибегать к внешнему инструментарию, а начать с использования встроенного Монитора ресурсов (resmon), благо интерфейс я все же увидел минут через 20 (!) после запуска приложения. С трудом переключаясь между элементами интерфейса, я прошелся по вкладкам ЦП, Память, Диск, Сеть и зафиксировал аномальную дисковую активность: на вкладке Диск, в разделе Работа диска, наблюдалось "повышенная" активность процесса WERFault.exe, который активно работал несколькими с файлами вида C:\ProgramData\Microsoft\Windows\WER\ReportQueue\Critical_6.1.7601_xxxx...xxxx_cab_xxxxxxxx. При этом поток данных был действительно большим, скорость превышала несколько мегабайт/секунду. Судя по всему (подтвердить снимком экрана не могу, просто забыл заскриншотить удаленный рабочий стол внешним скринером) похожих процессов было несколько, и все они работали с аналогичными файлами в дереве директорий с корнем в C:\ProgramData\Microsoft\Windows\WER\ReportQueue\. Никакой другой нетипичной активности в системе не наблюдалось, поскольку и этого системе хватало сполна, отсюда был сделан вывод, что причиной торможения системы является сильно нагруженная дисковая подсистема (шина SATA, модель винчестера ST3500413AS).

Затем я попытался устранить лишнюю нагрузку на систему и удалить один установленный компонент командой:

msiexec /uninstall {XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX} /q UNINSTALLPASSWORD=""

.. процесс msiexec.exe наглухо вис, показывая, что работает с хранилищем. При этом процессы, относящийся к деинсталлируемому ПО успешно были выгружены из памяти, однако сам msiexec упорно не хотел завершать свою работу. Все попытки инсталляции различных дистрибутивов заканчивались тем же "подвисанием" установщика, который просто стопорился на каком-нибудь из окон процесса установки, одним словом приложения не устанавливались. Общая производительность станции была, как уже отмечалось, очень низкая, низкая настолько, что порой невозможно было переключиться из окна в окно (!), окна приходилось просто сворачивать, только что бы добраться до находящегося на заднем плане окна :)
Тем не менее, первая подсказка у нас уже есть, сперва я попытался открыть в проводнике каталог C:\ProgramData\Microsoft\Windows\WER\ReportQueue\, с которым так активно работали процессы WERFault. Директория относилась к системному механизму WER.

WER используется разделенные пути очередей отладочных данных:

• %PROGRAMDATA%\Microsoft\Windows\WER -- для дампов процессов, запущенных в контексте Система или с повышенными привилегиями.
• %LOCALAPPDATA%\Microsoft\Windows\WER -- для дампов всех остальных процессов (в том числе уровня пользователя);

Очевидно, что в нашем случае используется второй (системный) вариант. Далее, в каталоге ReportQueue было обнаружено большое количество подкаталогов такого вот примерно вида:

Обратите внимание на время, отраженное в левом столбце, такое впечатление, что директории создавались механизмом WER со скоростью одна директория в одну-две минуты, при этом происходила запись огромного количества данных в файлы внутри каждой из указанных директорий. С чего бы это механизму WER вести себя подобным образом? Получается, если WER у нас с большой скоростью собирает данные для отправки, то в системе у нас с большой частотой что то падает!! Что еще добавляло нагрузки на систему в целом, так это то, что папки в каталоге ReportQueue обозначались синим цветом, что намекает на использование сжатия NTFS. Но не смотря на жуткие тормоза, спустя продолжительное время, мне все же удалось войти в одну из перечисленных директорий и взглянуть на её содержимое:

Вот так выглядит комплект данных для отправки отчета разработчикам. Глядя на размер файла CBS.log, я начал смутно догадываться о причинах медленной работы системы :) ведь файл журнала компонентной модели присутствовал в каждой поддиректории и каждый раз копировался в новую. В последствии, в зависимости от системных настроек, вся эта гигантская прорва информации еще и пытается каким-либо образом закачаться на локальный/удаленный сервер отчетов. Попытаемся разобраться в предназначении каждого файла из комплекта отправки:

После изучения содержимого каталога отправки становится очевидным, что WER готовит "отчет" об инциденте, куда включает все необходимые (?) файлы для передачи разработчику. Однако, почему происходило бесконечное создание фактически одинаковых пакетов отсылки? Вероятно, WER действовал в пределах нормы, просто в системе в тот момент что-то очень часто "падало", что и приводило к постоянной генерации отчетов. Давайте попытаемся разобраться что именно. Под рукой у нас для этого имеется все необходимое, а именно пара файлов с именами WER4BA8.tmp.hdmp и WER5644.tmp.mdmp, которые являются ничем иным как разными версиями дампа приложения. Не очень хорошо пока разбираюсь в структуре памяти процесса и не понимаю, что мне могут дать в данной ситуации данные кучи, поэтому откроем любой из этих файлов в отладчике WinDbg, благо в версии 6.12.0002.633 отладчик позволяет открывать и расширение .mdmp и .hdmp (в более ранних версиях могли иметься ограничения). При анализе дампа через команду !analyze -v мы видим имя сбойного процесса (PROCESS_NAME: TrustedInstaller.exe) и ниже по тексту стек вызовов момента падения:

Как мы помним, TrustedInstaller.exe является ключевым модулем для выполнения операций со стеком обслуживания. Судя по стеку вызовов, процесс TrustedInstaller.exe (Установщик модулей Windows) находился в момент сбоя в ожидании какого-то внешнего события, быть может ждал запуска/готовности какого-то сервиса (службы) посредством функций библиотеки sechost.dll (Host for SCM/SDDL/LSA Lookup APIs). В стеке мы видим функцию StartServiceCtrlDispatcherW, которая устанавливает связь главного потока процесса службы с Диспетчером управления службами (SCM), и вызывается в тот самый момент, когда SCM запускает процесс службы. Но вот какой именно службы (вероятно, имеется в виду одноименная служба Установщик модулей Windows) и нормально ли завершился процесс запуска, можно сказать только отлаживая код.

Двигаемся далее, мы выяснили что падает TrustedInstaller.exe, вопрос почему он падает с завидным постоянством? Ну упало один раз, с кем не бывает :) но зачем же так часто? Выходит, что бы часто падать, необходимо часто запускаться, кто-то постоянно создает задачи на установку пакетов. Вот тут то мы вспоминаем, что у нас в нашей корпоративной среде используется агент SCCM 2012. Что это такое? Выдержка из Wikipedia:

System Center Configuration Manager (SCCM, ранее SMS) — продукт для управления ИТ-инфраструктурой на основе Microsoft Windows и смежных устройств. Предоставляет такие возможности, как: управление обновлениями, развёртывание ПО и операционных систем, интеграция с NAP, инвентаризация аппаратного и программного обеспечения, удалённое управление, управление виртуализированными и мобильными системами на базе Windows.

Очень модная в данный момент штука, чрезвычайно громоздкая, написанная на старом бейсике начала 90-х годов и скомпилированная с опциями максимизации размера бинарного файла (шутка) :) Так вот этот самый агент SCCM и спамил нам постоянно задачи на установку обновлений операционной системы. Вроде как разобрались что именно падает и кто постоянно создает эти падающие впоследствии задачи. Но почему TrustedInstaller.exe падает? Первое что приходит на ум, так это проанализировать файл журнала компонентной модели CBS.log и поискать ответ в нем. Приведу основные, самые интересные (на мой взгляд), выдержки из этого файла, поскольку целиком файл занял порядка 1 гигабайта, вставлять его полностью не вижу возможности да и смысла, поэтому перечислим лишь основные моменты:

Во-первых, бросается в глаза код ошибки 0x800f0805, намекая на битые пакеты (?). Далее в файле можно увидеть интересные сообщения: "Store corruption detected" и "MissingWinningComponentKey on resource", что сразу же наводит нас на мысль о повреждении хранилища компонентов.

Решение

Скорее по привычке, нежели обоснованно, первой я запустил команду Sfc с ключом /verifyonly и тут же получил следующую ошибку:

Эта лишняя (в данной ситуации) команда дала понять, что стек обслуживания кем-то занят. Скорее всего, со стеком одновременно невозможно работать нескольким источникам. Вспоминаем, про TrustedInstaller.exe, однако его снятие нам ничего не даст, поскольку работает агент SCCM, который постоянно создает задачи на установку. Поэтому, при помощи диспетчера задач рекомендуется снимать следующие процессы (в заданной последовательности):

1. CcmExec.exe;
2. CmRcService.exe;
3. msiexec.exe;
4. TrustedInstaller.exe;
5. wermgr.exe - если присутствует;

Поле этого вся активность со стеком обслуживания прекратилась. Далее была выполнена команда:

DISM /Online /Cleanup-Image /ScanHealth

результатом выполнения которой было следующее сообщение "Выполнение операции scanhealth завершено, см. журнал по адресу %windir%\logs\CBS\Checksur.log. Операция успешно завершена.":

с рекомендацией проверить файл %WinDir%\Logs\CBS\CheckSUR.log. Привожу выдержку ключевых моментов содержимого данного файла:

Видно, что DISM исправил 376 ошибок. После этого была произведена перезагрузка системы и SCCM продолжил штатную установку обновлений. Более проблем у пользователя не возникало.

Выводы

Инцидент породил слишком большое количество вопросов.

• Почему у нас агент обновления ругается на битые пакеты? Приходят ли они действительно битые с сервера обновлений или причина в другом?
• Почему TrustedInstaller не отслеживает повреждения хранилища пакетов/компонентов и падает вместо завершения с кодом ошибки? Ошибка в коде модуля?
• Почему WER копирует в ReportQueue большие объемы данных, тем самым сильно нагружая систему? А если устроить циклическое падение множества процессов в системе, то WER просто "положит" станцию, как в этом случае?

Я думаю, что все эти вопросы останутся без ответов, поскольку мы не докопались до сути проблемы. Ну а исключить возможность возникновения подобных ситуаций в будущем можно через консоль Configuration Manager Console. Как один из вариантов: Software Library - Software Updates - Software Update Groups, задать для требуемой группы Alert, а вот уже на Alert'ы потом повесить необходимые действия. Возникает вопрос в более тонкой интеграции агента SCCM со стеком обслуживания с целью отслеживания ситуации с падающим процессом TrustedInstaller.exe на клиентской машине и остановке задач по установке компонентов. В нашем случае он продолжал ставить задания на запуск установки обновлений.