Дело о временных профилях реестра
Служба поддержки клиентов корпорации Microsoft является одним из крупнейших пользователей утилит Sysinternals и они часто посылают мне письма с рассказами о проблемах, которые они решили с помощью наших утилит. Случай, о котором я расскажу в этой статье, особенно интересен тем, что он затронул большое количество пользователей, и в процессе решения проблемы использовалась одна из наименее известных функций Process Monitor. Все началось с того, что один из клиентов обратился в службу поддержки Microsoft с жалобой о том, что некоторые из их пользователей иногда сталкиваются со следующим сообщением об ошибке, когда входят в систему:
Вследствие этого Windows создала временный профиль для процесса входа пользователя в систему. Профиль пользователя располагается в директории %UserProfile%, в которую приложения сохраняют файлы конфигураций и данных (для каждого пользователя они свои), а также файл ветви реестра в директории %UserProfile%\Ntuser.dat, который процесс Winlogon загружает во время входа пользователя в систему. Приложения сохраняют настройки пользователя в ветви системного реестра путем вызова функций, обращающихся к корневой директории HKEY_CURRENT_USER (HKCU). Факт потери пользователем доступа к их профильным файлам перевел рассматриваемую проблему в разряд критических, поскольку каждый раз, когда это случалось, пользователь терял все свои настройки, а также доступ к файлам, хранившимся в его профильной директории. В большинстве случаев пользователи обращались в службу поддержки компании, где их просили попытаться перезагружать компьютер и входить в систему до тех пор, пока проблема не решится сама по себе.
Как обычно бывает в таких случаях, первым делом специалисты службы поддержки Microsoft спрашивали пользователей о конфигурации системы, установленном программном обеспечении и обо всех недавних изменениях, которые их компания вносила в их систему. В ходе анализа собранных данных был обнаружен тот факт, что на всех системах, которые были подвержены этой проблеме, недавно был произведен апгрейд до новой версии ICA-клиента от Citrix Corporation, приложения для работы с удаленным рабочим столом. Microsoft связалась с поддержкой Citrix, чтобы узнать, известно ли им о каких-либо ошибках, связанных с новым клиентом. Они ответили на этот вопрос отрицательно, но при этом сказали, что займутся расследованием этого дела.
Неуверенные в том, что причиной возникновения проблемы с профилями пользователей является обновление ICA-клиента, поддержка Microsoft проинструктировала своего клиента о том, как включить функцию ведения лога процессов работы с профилем. Сделать это можно внеся изменения в соответствующий ключ реестра, как описано в этой статье базы знаний. Клиент внес указанные изменения в свои системы и вскоре после этого получил новые сообщения от пользователя, столкнувшегося с проблемой, связанной с профилем. Они сделали копию лога профиля %SystemRoot%\Debug\UserMode\Userenv.log и отослали ее в Microsoft. Лог не смог дать ответ почему случается данная проблема, однако содержал в себе одну важную подсказку: он указывал на то, что профиль пользователя не смог загрузиться из-за ошибки 32, которой является ошибка ERROR_SHARING_VIOLATION:
Когда процесс открывает файл, он определяет, какие виды совместного доступа поддерживает этот файл. Если процесс производит запись в этот файл, он может, например, позволять другим процессам производить чтение из этого файла, но запрещать запись в него. Наличие записи об ошибке совместного доступа в файле лога означало, что другой процесс открыл ветвь системного реестра пользователя в режиме, который был несовместим с тем режимом, в котором процесс входа пользователя в систему хотел открыть файл.
А тем временем все больше клиентов по всему миру стало обращаться в Microsoft и Citrix с той же самой проблемой, и каждый из них тоже недавно устанавливал новый ICA-клиент. Тогда поддержка Cintrix сообщила, что они подозревают, что ошибка совместного доступа могла быть вызвана одним из процессов ICA-клиента - Ssonvr.exe. Во время инсталляции ICA-клиент регистрирует библиотеку Network Provider DLL (Pnsson.dll), которую вызывает Windows Multiple Provider Notification Application (%SystemRoot%\System32\Mpnotify.exe) во время загрузки системы. Сам Mpnotify.exe запускается процессом Winlogon во время входа в систему. Библиотека Citrix запускает процесс Ssonvr.exe асинхронно процессу входа пользователя в систему:
Единственным недостатком этой теории являлось то, что разработчики из Citrix настаивали на том, что этот процесс не пытается загружать какой-либо профиль пользователя из системного реестра или даже читать любой ключ или значение оттуда. И Microsoft, и Citrix были озадачены.
Microsoft создала версию Winlogon и ядра, собирающих дополнительную диагностическую информацию и попыталась воспроизвести проблему в лаборатории, на системах имеющих ту же конфигурацию, что и компьютеры клиента, но все безуспешно. Клиент даже не смог еще раз вызвать проблему на измененном образе Windows, что произошло, скорее всего, потому, что образ изменил время реакции системы настолько, что это помогло избежать проблемы. В этой ситуации один из инженеров поддержки Microsoft предложил, чтобы клиент фиксировал все последствия процесса входа в систему с помощью Process Monitor.
Есть несколько способов настроить Process Monitor для запись операций входа в систему: первый подразумевает использование Sysinternals PsExec для ее запуска в нулевой сессии, чтобы утилита смогла "пережить" выход и последующий вход в систему; второй заключается в применении функции создания лога загрузки для фиксации активности в системе, начиная с ранних этапов загрузки и включая вход в систему. Инженер выбрал второй способ. Он сказал клиенту запустить Process Monitor на одной из систем, на которой постоянно сталкивались с рассматриваемой проблемой, выбрать опцию Enable Boot Logging в меню Options, и произвести перезагрузку, выполняя все ее шаги до тех пор, пока проблема не проявится. Эта процедура вносит изменения в драйвер Process Monitor, чтобы утилита запускалась на ранних этапах загрузки и регистрировала активность в файл %SystemRoot%\Procmon.pmb. Как только пользователь столкнулся бы с проблемой, он должен был снова запустить Process Monitor, что привело бы к окончанию процесса записи лога, и Process Monitor преобразовал бы загрузочный лог в стандартный файл лога Process Monitor.
После нескольких попыток пользователь успешно повторил ощибку и зафиксировал загрузочный файл лога, который затем отправил в Microsoft. Инженеры поддержки Microsoft просмотрели этот лог и обнаружили ошибку совместного доступа, возникшую, когда Winlogon пытался загрузить ветвь системного реестра:
Исходя из операций, непосредственно предшествующих появлению ошибки, было очевидно, что Ssonsvr.exe был тем процессом, для которого открывалась ветвь. Вопрос состоял в том, почему Ssonsvr.exe открывал ветвь системного реестра? Чтобы дать на него ответ инженеры обратились к функциям Process Monitor по отслеживанию активности стека. Process Monitor фиксирует состояние стека вызовов для каждой операции. Просматривая стек вызовов, зачастую вы можете определить корень операции, что не всегда можно определить, зная лишь то, какой процесс эту операцию запустил. Например, стек может показать вам, что библиотека DLL, загруженная в процесс, выполняет операцию, и, если у вас правильно настроено отображение символов и вызов происходит в образе Windows или другом образе, для которого проведена настройка символов, он даже покажет вам названия ответственных за это функций.
Стек Ssonsvr.exe, открытый из файла Ntuser.dat, показал, что не Ssonsvr.exe был ответственен за вызов операции, а Windows Logical Prefetcher:
Впервые появившийся в Windows XP Logical Prefetcher представляет собой компонент ядра системы, который отслеживает первые десять секунд запуска процесса, записывая директории и части файлов, к которым обратился данный процесс за это время, в файл в директории %SystemRoot%\Prefetch. Для того, чтобы несколько исполняемых файлов, имеющие одинаковые имена, но расположенные в разных директориях, имели свой собственный prafetch-файл, Logical Prefetcher дает этому файлу имя, составляемое из имени исполняемого образа и хэша, полученного на основе пути хранения этого исполняемого образа (например, NOTEPAD.EXE-D8414F97.pf). Вы можете увидеть файлы и директории, которые записал Logical Prefetcher во время последнего запуска приложения, используя утилиту Sysinternals Strings для сканирования prefetch-файла:
strings <prefetch file>
Во время следующего запуска приложения Logical Prefetcher, выполняющийся в контексте первого потока процесса, просматривает prefetch-файл. Если таковой существует, он открывает каждую директорию, присутствующую в списке, чтобы перенести метаданные директории в память, если там их еще нет. Затем Logical Prefetcher отображает в память каждый файл, перечисленный в prefetch-файле, и устанавливает ссылки на те их части, к которым приложение обращалось во время последнего запуска, таким образом, они так же загружаются в память. Logical Prefetcher может ускорить запуск приложения, потому что генерирует большие, последовательные потоки ввода/вывода, вместо того, чтобы заниматься организацией доступа к маленьким случайным частям данных файла, что обычно делает приложение во время запуска.
Обнаружение связи между Logical Prefetcher и проблемой профилей поставило перед инженерами поддержки новые вопросы. Почему Logical Prefetcher подгрузил файл ветви пользователя в контексте Ssonsvr.exe, тогда как сам Ssonsvr.exe никогда не обращается к профилям системного реестра? Чтобы получить ответ на этот вопрос, инженеры поддержки Microsoft обратились к команде разработчиков Logical Prefetcher. Прежде всего, разработчики отметили, что чтение из системного реестра Windows XP производится из операций ввода/вывода кэшированных файлов с использованием системной памяти, что означает, что поток опережающего чтения Cache Manager активно считывает части ветви. Так как этот поток опережающего чтения выполняется в процессе System и Logical Prefetcher связывает активность этого процесса с запускающимся в настоящее время процессом, эта последовательность задержек в процессе запуска и последующей активности во время загрузки и входа в систему могла послужить причиной того, что Logical Prefetcher получил доступ к ветви в качестве части процесса запуска Ssonsvr.exe. Если бы при следующих загрузке и входе в систему порядок этих событий немного изменился, то Winlogon столкнулся бы с Logical Prefetcher, что мы и видим в записанном файле лога.
Logical Prefetcher выполняется прозрачно по отношению к другой активности в системе, однако его ссылки на файл могут привести к ошибкам совместного доступа, в данном случае на Windows XP (на серверных системах Logical Prefetcher занимается только подготовкой запуска системы, причем делает он это строго перед продолжением выполнения загрузочных процессов и синхронизирован с ними). По этой причине на системах Windows Vista и Windows 7 Logical Prefetcher использует драйвер минифильтра файловой системы Fileinfo (%SystemRoot%\System32\Drivers\Fileinfo.sys) для отслеживания потенциальных ошибок совместного доступа и предотвращения их появления, для чего он останавливает вторую операцию, желающую получить доступ к файлу, которым в данный момент пользуется Logical Prefetcher, до тех пор, пока он его не закроет.
Теперь, когда проблема была решена, Microsoft и Citrix задумались над тем, какие действия предпринять клиентам, чтобы избежать появления ошибки, на то время, пока Citrix работала над обновлением для ICA-клиента, которое предотвратило бы ошибку совместного доступа. Первым вариантом является отключение функции подгрузки файлов для приложения, вторым - написание скрипта для процесса выхода из системы, который удалял бы prefetch-файлы Ssonsvr.exe. Citrix опубликовала свои рекомендации в этой статье, а Microsoft - в этой статье. Обновление для ICA-клиента, которое стало доступно несколькими днями позже, изменило время запуска библиотеки DLL провайдера сети на 10 секунд после запуска Ssonsvr.exe, до того, как контроль будет передан Mpnotify.exe. Поскольку Winlogon ожидает завершения Mpnotify.exe для того, чтобы выйти до того, как пользователь войдет в систему, Logical Prefetcher не будет относить запросы на доступ к файлам куста пользователя, принадлежащие Winlogon, к процессу запуска Ssonsvr.exe.
Как я уже сказал во введении, я нахожу этот случай особенно интересным, поскольку в нем проявляются малоизвестная функция Process Monitor - ведение лога загрузки системы - и полезность показателей активности стека для анализа первопричины проблемы - два ключевых инструментальных средства из арсенала для решения проблем, которые каждый может использовать. Он также показывает нам то, как успешная диагностика может помочь придумать временный обход проблемы в ситуациях, когда решения не существует или вам приходится ждать, пока вендор его предоставит. Еще одна проблема, успешно решенная при помощи Process Monitor. Пожалуйста, продолжайте присылать мне скриншоты и файлы логов для решенных вами проблем.