Казалось, Холмс совсем отошел от дел. Он строго-настрого наказал миссис Хадсон отправлять всех визитеров в Скотланд-Ярд. А сам предавался курению трубки, игре на скрипке и своему новому увлечению — поездкам по вечернему Лондону на электрическом велосипеде. Однако в то утро посетители оказались исключительно настойчивыми.

Выйдя на шум, мы столкнулись с запыхавшейся миссис Хадсон: «Мистер Холмс, эти джентльмены заявляют, что никуда не уйдут, пока не получат вашу аудиенцию. Они уверены, что вы их примете. Не могу же я поселить их внизу!». Понизив голос, она доверительно добавила: «Они в штатском, но думаю, что это военные».

Холмс незаметно посмотрел сверху на посетителей и, кажется, узнал одного из них: «Что ж, пригласите их ко мне». Оба посетителя, действительно, отличались военной выправкой и короткими стрижками. Первый лет сорока пяти, высокий, сухощавый, с узким лицом и тонкими язвительными губами. Второй помладше лет на десять и пониже, с бычьей шеей и телосложением как у столба в регби. Безупречно пошитые костюмы и дорогие туфли давали понять, что перед нами не рядовые служаки.

Инцидент в секретном ведомстве

Расположившись в креслах, они поблагодарили Холмса за уделенное время, и старший быстро перешел делу.

В их ведомстве произошел неприятный инцидент. Сотрудник, занимавшийся обслуживанием важнейшего сервера, вывел его из строя примерно на полтора часа. За это время произошли события, которые не удалось вовремя обработать на сервере. И это негативно отразилось на национальной безопасности. Сотрудника заподозрили в государственной измене. Он в свою очередь возложил всю вину на Windows.

Тут Холмс вопросительно приподнял брови. Как по сигналу, младший посетитель начал выстреливать подробности.

— Оператор обслуживал ПО на сервере. Он выполнил все предварительные процедуры и перезагрузку. Затем он внес согласованные изменения, это заняло около часа. Потом снова перезагрузил сервер. Но в этот раз, как он утверждает, возможность удаленного подключения пропала надолго.
— У него были права администратора на сервере?
— Нет. Для этих задач обслуживания они не требовались.
— Что он должен был сделать по инструкции?
— Четких инструкций в этой процедуре не было, но он должен был сообщить в поддержку. Вместо этого он якобы зашел в iLo и через удаленную консоль увидел экран «Подготовка Windows».

Рассказчик быстро достал телефон и показал нам картинку: «Вот такой».

— Он якобы сделал снимок экрана. Утверждает, что система была в таком состоянии почти полтора часа, после чего загрузилась как обычно.
— Почему вы ему не верите?
— Снимок экрана легко сфабриковать. Внутреннее расследование не подтвердило его версию.

Холмс пожал плечами и посмотрел на старшего. Тот принял эстафету:

— Этот сотрудник – племянник очень высокопоставленного лица. Ошибиться никак нельзя. А секретная сущность сведений не позволяет расширить круг лиц, которые имеют доступ к серверу. Ваша репутация, Холмс, настолько безупречна, что мы приняли решение обратиться к вам.

Холмс коротко кивнул, и оба посетителя немедленно поднялись с кресел.

— Не смеем больше отнимать ваше время, детектив. Позвоните по этому номеру, и вам доставят обезличенные данные с того сервера. Но только необходимый минимум.

Журналы событий

После визита гостей настроение Холмса заметно улучшилось. Похоже он соскучился по расследованиям!

— Что вы об этом думаете, Ватсон?
— Думаю, они нас водят за нос. С их огромными бюджетами перезагрузка одного сервера не должна приводить к пробелам в обработке данных. Похоже, кто-то копает под высокопоставленное лицо, а эти два джентльмена представляют его интересы.
— Действительно, вешать лапшу на уши — их конек. А что скажете по сути инцидента? Какие данные нам следует запросить?

Я уже успел проконсультироваться с ChatGPT, поэтому был готов к вопросу:

— Можно определить длительность перезагрузки Windows по журналам событий. В журнал System записываются события остановки службы журналирования и ее запуска, ИД 6006 и 6005 соответственно.

Холмс одобрительно кивнул и указал взглядом на оставленную посетителями визитку с номером телефона. Через несколько часов фельдъегерь доставил нам флешку с экспортированными журналами событий. Я быстро сделал выборку в PowerShell.

Get-WinEvent -ErrorAction 0 -FilterHashTable @{
    ID = '6005', '6006'
    #saved log
    Path='C:\temp\system.evtx'
    #online log
    #LogName='System'
}

   ProviderName: EventLog
   
TimeCreated          Id LevelDisplayName Message
-----------          -- ---------------- -------
13/06/2023 13:08:09           6005 Information      The Event log service was started.
13/06/2023 13:04:11           6006 Information      The Event log service was stopped.
13/06/2023 10:42:22           6005 Information      The Event log service was started.
13/06/2023 10:38:23           6006 Information      The Event log service was stopped.

— Смотрите, Холмс! Действительно, есть две перезагрузки, но оба раза между событиями 6006 и 6005 проходило лишь около четырех минут. Выходит, что оператор солгал!

Детектив посмотрел на меня с легким сожалением:

— Ватсон, человека подозревают в госизмене… Подумайте, что происходит во время перезагрузки Windows. Вот вы нажали кнопку… и?
— Система закрывает все запущенные программы, потом завершает сеанс, потом…

Детектив поднял вверх указательный палец останавливая меня. Я покраснел. Как же я не подумал об этом! ChatGPT немедленно выдал, что если включен аудит завершения пользовательского сеанса, в журнале Security должно быть событие 4647.

Get-WinEvent -ErrorAction 0 -FilterHashTable @{
    ID = '4647'
    #saved log
    Path='C:\temp\security.evtx'
    #online log
    #LogName='Security'
}

   ProviderName: Microsoft-Windows-Security-AuditingTimeCreated          

Id LevelDisplayName Message
-----------          -- ---------------- -------
13/06/2023 11:41:21           4647 Information      User initiated logoff:... 
13/06/2023 10:38:01           4647 Information      User initiated logoff:... 

С аудитом на сервере было все в порядке. И теперь объяснение оператора стало похоже на правду! Первая перезагрузка началась немедленно после выхода из системы. Во втором случае пользователь завершил сеанс в 11:41, а служба журналирования остановилась в 13:04. То есть Windows ждала чего-то почти полтора часа. И только после этого ушла в перезагрузку, которая длилась четыре минуты.

— Холмс, но как же нам узнать, что Windows делала все это время?
— Это элементарно, Ватсон! Какие ассоциации у вас возникают при виде экрана «Подготовка Windows»?
— Гм… Установка обновлений?
— Не совсем, но связь есть. Вам нужен журнал системы обслуживания, CBS.log!

CBS.log

Холмс раскурил трубку и откинулся в кресле. Всем своим видом он давал понять, что ему это уже неинтересно, а завершить расследование я смогу и без его помощи.

Для начала мое внимание привлекли события через 10 минут после первой перезагрузки.

2023-06-13 10:52:53, Info       CBS    Idle scavenging initiated
2023-06-13 10:52:53, Info       CBS    Starting TiWorker initialization.

За ними следовали сотни строк с перечислением различных пакетов.

— Что все это значит, Холмс?
— Scavenging (уборка мусора) — это стандартная процедура системы обслуживания. Выполняется инвентаризация установленных пакетов с целью удаления ненужных. Эти действия также известны как очистка папки WinSxS или очистка обновлений Windows.

Выходит, что через 10 минут после первой перезагрузки ОС перешла в бездействие и начались фоновые операции очистки. Продравшись через сотни однообразных строк, я нашел еще кое-что интересное.

2023-06-13 11:41:22, Info       CBS    Idle scavenging stop signaled.
2023-06-13 11:41:22, Info       CBS    Trusted Installer signaled for shutdown, going to exit.
2023-06-13 11:41:22, Info       CBS    A system shutdown was initiated while idle scavenging was running
2023-06-13 11:41:22, Info       CBS    Shtd: Prepare for shutdown processing.
2023-06-13 11:41:23, Info       CBS    SetProgressMessage: progressMessageStage: 0, ExecuteState: ExecuteStateNone, SubStage: 0
2023-06-13 11:41:23, Info       CBS    Shtd: PreshutdownTimeout: 3600000ms, BlockTimeIncrement: 900000ms
2023-06-13 11:41:23, Info       CBS    Shtd: progress thread started
2023-06-13 11:42:29, Info       CBS    Failed to stop scavenging [HRESULT = 0x800705b4]
2023-06-13 11:42:29, Info       CBS    Shtd: progress thread terminating. [HRESULT = 0x00000000 - S_OK]
2023-06-13 11:42:29, Info       CBS    Shtd: progress thread terminated normally
2023-06-13 11:42:29, Info       CBS    Trusted Installer is shutting down because: SHUTDOWN_REASON_NOTIFICATION:PRESHUTDOWN
2023-06-13 11:42:29, Info       CBS    Starting shutdown processing in TrustedInstaller service.
2023-06-13 11:42:29, Info       CBS    Shtd: Begin shutdown processing.
2023-06-13 11:42:29, Info       CBS    Shtd: Prepare for shutdown processing.
2023-06-13 11:42:29, Info       CBS    SetProgressMessage: progressMessageStage: 0, ExecuteState: ExecuteStateNone, SubStage: 0
2023-06-13 11:42:29, Info       CBS    Shtd: PreshutdownTimeout: 3600000ms, BlockTimeIncrement: 900000ms
2023-06-13 11:42:29, Info       CBS    Shtd: progress thread started
2023-06-13 11:42:34, Info       CBS    Session: 31038949_882832442 initialized by client CbsTask, external staging directory: (null), external registry directory: (null
2023-06-13 11:42:34, Info       CBS    Startup: Mark session as corrupt since it is neither complete nor pended, Session: 31038949_882832442, State:Installed

По времени эти операции точно совпадали с завершением сеанса перед второй перезагрузкой. Получив сигнал о выключении, система обслуживания начала подготовку к нему. В глаза бросилось PreshutdownTimeout: 3600000ms. Это ровно час ожидания перед выключением Windows! Также система обслуживания пометила эту сессию поврежденной, поскольку она не завершилась и не отложилась.

Спустя ровно час, CBS отчиталась, что время ожидания истекло и никакого прогресса за этот период не произошло. На протяжении следующих 22 минут в логе не было никаких событий. А затем уже появились сообщения, что обработка состояния пакетов завершена. Дальше система просто перешла к завершению работы.

2023-06-13 12:42:29, Info       CBS    Shtd: Timed out waiting for shutdown processing to complete - no progress detected in last 3600000 milliseconds
2023-06-13 13:04:04, Info       CBS    FinalCommitPackagesState: Completed persisting state of packages
2023-06-13 13:04:04, Info       CBS    Enabling LKG boot option
2023-06-13 13:04:04, Info       CBS    Exec: Processing complete.  Session: 31038949_882832442

CBS.log подтвердил версию оператора — полуторачасовая задержка была вызвана системой обслуживания, причем целый час она прождала у моря погоды.

Эпилог

С помощью всего трех журналов оказалось несложно восстановить цепочку событий. Но у меня остались небольшие сомнения:

— Холмс, но не мог ли оператор сфабриковать эти записи?
— Для этого нужны права администратора, потому что журналы хранятся в системной папке. Нам сказали, что полных прав у него не было. Иначе это была бы совсем другая история, друг мой!

---

По традиции напоминаю, что детективные истории о Холмсе я пишу для вашего и своего развлечения. Если вы не воспринимаете такой стиль изложения, в блоге есть другие записи в традиционном ключе.