21.04.2021 07:00
vhuman 13 2300 Источник

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

В то же время умение работать с логами - очень ценный и полезный навык. Я бы сравнил работу с логами с поеданием овсянки. Есть овсянку - полезно == уметь анализировать логи - полезно. Ну, а для того, чтобы овсянка стала вкуснее, в нее я добавлю топпинг - интересный сценарий. Чем более загадочной выглядит проблема, тем интереснее становится анализ логов, и ты смотришь уже не просто на строки текста, а распутываешь клубок из улик и доказательств, проверяешь или опровергаешь теории.

Ну что, наливаем чаек, сейчас мы будем расследовать - Детектив с Кластером Hyper-V

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

0. По традиции - все начиналось с ошибки.

Как и в любом детективе, начало весьма обычное: есть конкретная проблема. В этом случае выглядела она как тикет от клиента с примерно таким содержанием: "Помогите! Задание падает с ошибкой - Processing FS2 Error: Failed to get VM (ID: 6fb62d8a-4612-4106-a8e7-8030de27119e) config path. [WMI] Empty result."

Когда есть конкретная ошибка, это уже хорошо. Сразу понятно: что-то явно сломано – это как стук в двигателе машины. Мы видим, что это ошибка в работе Backup job - задании резервного копирования для нескольких виртуальных машин. В этой ошибке даже есть аббревиатура [WMI], а это уже зацепка!

Как говорит википедия: WMI — это одна из базовых технологий для централизованного управления и слежения за работой различных частей компьютерной инфраструктуры под управлением платформы Windows. А я бы сказал: WMI - это технология, используя которую Veeam B&R отправляет запросы на Hyper-V хост или кластер. Это могут быть такие запросы, как создание чекпоинта, удаление чекпоинта, создание коллекции, добавление VM в коллекцию и так далее. 

Зная это, мы понимаем, что имеем дело с Hyper-V инфраструктурой. (Далее надо будет понять, кластер это или же одна нода). А проблема связана с WMI запросом, который вернул пустое значение. (Empty result)

Промежуточный вывод: задание резервного копирования для пяти виртуальных машин на гипервизоре Hyper-V завершилось успешно для трех машин, а для двух выдало ошибку - Failed to get VM (ID: 6fb62d8a-4612-4106-a8e7-8030de27119e) config path. [WMI] Empty result.

1. Приступаем к сбору логов

С чего же начинается анализ логов? - В первую очередь со сбора этих самых логов! В некоторых случаях собрать правильные логи - это уже полдела! Напоминаю, мы расследуем конкретное задание (Job), и портфель с логами нам нужен именно для этого задания.

Дело в том, что в задании помимо Veeam сервера задействованы другие компоненты. Это и Hyper-V ноды, на которых крутятся машины из задания, и репозиторий, на который пишутся файлы бэкапа, и прочие прокси. В общем случае таких серверов может быть достаточно много. И что же теперь? Нам лазать по всем серверам и копировать файлы? Нет, в нашей ситуации процесс сбора логов - полуавтоматический, благо в VBR есть встроенный помощник для таких дел. Есть даже статья с анимацией. Поэтому, в консоли Veeam переходим в Menu > Help > Support information

При выборе опции (Export logs for this job), Veeam B&R соберет файлы со всех компонентов (прокси = Hyper-V ноды), вовлеченных в задание. Также будет добавлен HTML отчет, который может очень сильно упростить анализ. Одним словом - песня, все логи в одном архиве, да ещё и отчетик прилагается.

2. Анализ собранной информации

Итак, распаковали архив и видим следующее:

  • Папка с логами, собранными с Veeam B&R сервера - storepc.dom1.loc

  • Папки с логами, собранными с двух Hyper-V нод - 19node1 и 19node2

  • Отчет по конкретному заданию - Critical FServers.html

Хммм, с чего же начать…..

А начинать, я считаю, надо от общего к частному. Общим в нашем случае будет HTML отчет - так как в нем мы видим общую информацию о выполнении задания за период времени, и можно прикинуть статистику. Ну и, конечно же, отчет более приятен человеческому глазу, чем сотни строк логов =)

2.1 Отчет задания, и зачем его смотреть

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

 Что же мы видим в отчете?

  1. Сервер FS4 падает с ошибкой;

  2. Через несколько минут - успешный Retry для сервера FS4

  3. Во время следующего штатного выполнения задания серверы FS2 и FS3 падают с этой же WMI-ошибкой

  4. Через несколько минут - успешный Retry для серверов FS2 и FS3

Вывод по анализу отчета: Из нашего списка машин при штатном выполнении задания некоторые падают, но обязательно отрабатывают с ретрая буквально через несколько минут. Установить закономерность падения машин невозможно, они падают рандомно. Также бывают абсолютно успешные штатные выполнения задания для всех машин.

Retry - специальная настройка задания, которая попытается повторить его выполнение только для тех VM, для которых не был создан бэкап. В настройках задания обычно указывается, сколько раз пробовать Retry и через какой промежуток времени после неудачи.

Теории о том, что:

  • есть проблемная машина или ряд проблемных машин;

  • есть проблемная Hyper-V нода ;

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

2.2 Логи задания: ищем стэк ошибки

Так как ошибка одна, но появляется для разных машин, то мы просто выбираем любое выполнение задания с ошибкой и анализируем его. Для начала идем в лог, который описывает обработку конкретной машины в задании - той, для которой вышла ошибка. Схема, по которой ищутся логи для задания - Veeam сервер\Backup\Название задания. В нашем случае это storepc.dom1.loc\Backup\Critical_FServers. Более подробно про структуру логов и где что лежит мы писали в отдельных статьях здесь и здесь.

В этой папке для задания резервного копирования можно встретить 3 типа логов:

  1. Agent - логи компонента, который занимается передачей данных (Veeam Agent - Data mover). Если в названии есть слово Target, значит - это лог агента, который записывал данные на репозиторий. Если это задание репликации, то Target будет в папке на сервере, который использовался в качестве целевого прокси и писал данные на хранилище данных гипервизора (Datastore) куда реплицируем. Если в названии есть слово Source, значит - это лог агента, который читал данные с хранилища данных гипервизора (Datastore). 

  2. Job - это лог задания целиком. При общении с сапортом можно смело говорить просто “джоба”, и вас поймут.

  3. Task - это лог подзадания (таски), из которого состоит задание (Job). Каждая виртуальная машина в задании обрабатывается отдельной таской, которая пишет свой отдельный лог.

Мы открываем файл, начинающийся с Task и содержащий название VM. В нем просто ищем ошибку. Обычно нажимаем CTRL+End - это перебрасывает нас в самый низ лога, и потом крутим колесико вверх, пока не увидим нужную нам ошибку.

[29.09.2020 08:04:21] <38> Info     [WmiProxy:19node1] HviGetVmConfigPath: <InputArguments><Hvi_LogName value="Critical_FServers\HvWmiProxy-STOREPC-19node1.log" /><Hvi_Host value="STOREPC-19node1" /><Hvi_Process value="00002870" /><Hvi_RequestId value="000000000000002d" /><Hvi_TimeoutMs value="3600000" /><VmId value="3564c574-8a83-42d2-aef4-46e7218d8ccc" /></InputArguments>
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 17
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 16
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 15
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 14
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 13
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 12
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 11
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 10
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 9
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 8
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 7
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 6
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 5
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 4
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 3
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 2
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CProxyRpcInvoker} object [03dd98cb]: Counter = 1
[29.09.2020 08:04:21] <42> Info     MRCReference: Release {CVeeamHvIntegrator} object [02ca5f28]: Counter = 1
[29.09.2020 08:04:21] <42> Error    Failed to get VM (ID: 3564c574-8a83-42d2-aef4-46e7218d8ccc) config path. [WMI] Empty result. (Veeam.Backup.ProxyProvider.CHvWmiProxyErrorException)
[29.09.2020 08:04:21] <42> Error       at Veeam.Backup.ProxyProvider.CHvWmiReconnectableRemoteCommand.InvokeInThread(Delegate dlg, Object[] args)
[29.09.2020 08:04:21] <42> Error       at Veeam.Backup.ProxyProvider.CHvWmiReconnectableRemoteCommand.DoInvoke(CHvWmiProxyRequestContextNdw context, Int32 reconnectsCount, Delegate dlg, Object[] args)
[29.09.2020 08:04:21] <42> Error       at Veeam.Backup.ProxyProvider.CHvWmiReconnectableRemoteCommand.Invoke[Ret](CHvWmiProxyRequestContextNdw context, Func`1 dlg)
[29.09.2020 08:04:21] <42> Error       at Veeam.Backup.ProxyProvider.CHvWmiVmRemoteManager2015.GetConfigPath(Guid vmID)
[29.09.2020 08:04:21] <42> Error       at Veeam.Backup.Core.HyperV.CHvVmSource2015..ctor(IVmBackupTask task, CBackupTaskSession taskSession, CBackup backup, CSmbLookupCache smbLookupCache, CHvSnapshotHolder snapshotHolder, CHvVssConnectionCreatorSet vssConnCreatorSet, IStopSessionSync sessionControl)
[29.09.2020 08:04:21] <42> Error       at Veeam.Backup.Core.HyperV.CHvBackupJobPerformer.CreateSource(CHvVmTask task, CBackupTaskSession taskSess)
[29.09.2020 08:04:21] <42> Error       at Veeam.Backup.Core.HyperV.CHvBackupJobPerformer.ExecuteTask(CHvVmTask task)

Стэк выглядит вот так, и нам он говорит, что был WMI запрос HviGetVmConfigPath: - этот запрос попытался получить путь до конфигурации VM по ID и в ответ получил пустой результат. Круто! Запрос! А дальше-то что?

А дальше нужно смотреть логи компонента, отвечающего за запросы, анализировать их, чтобы наконец построить теорию.

2.3 Логи WMI запросов на Hyper-V ноду с сервера Veeam

Нам нужны логи Veeam компонента, который отправляет WMI запросы на Hyper-V ноде. 

Подсказка: его мы видим в стеке с ошибкой который я показал выше :

Host value="STOREPC-19node1"
LogName value="Critical_FServers\HvWmiProxy-STOREPC-19node1.log

 Идем в папку, собранную с интересующей нас Hyper-V ноды 19node1

И находим лог компонента, отвечающего за WMI запросы - HvWmiProxy. Ошибиться сложно, поскольку файл начинается с HvWmiProxy и заканчивается либо названием ноды, либо кластера (когда запросы отправляются в кластер). В нашем случае это название ноды - HvWmiProxy-STOREPC-19node1.log

Здесь мы находим уже весь запрос: SELECT Name, ElementName, __RELPATH FROM Msvm_ComputerSystem WHERE Name = "6fb62d8a-4612-4106-a8e7-8030de27119e"

И тут мы можем видеть, что он вернул пустой результат (Empty result). А что вообще он должен возвращать-то? Вопрос хороший, давайте посмотрим, как отработал успешный запрос для другой машины.

[29.09.2020 08:08:53.995] <  7748> hwp| HviGetVmConfigPath
[29.09.2020 08:08:53.995] <  7748> hwp|   Hvi_CommitedRequestId__ARRAY = { 00001f0000000012, 00001f0000000011, 00001f0000000010 }
[29.09.2020 08:08:53.995] <  7748> hwp|   Hvi_DevelopMode = True
[29.09.2020 08:08:53.995] <  7748> hwp|   Hvi_Host = STOREPC-19node1
[29.09.2020 08:08:53.995] <  7748> hwp|   Hvi_LogName = Critical_FServers\HvWmiProxy-STOREPC-19node1.log
[29.09.2020 08:08:53.995] <  7748> hwp|   Hvi_Process = 00002440
[29.09.2020 08:08:53.995] <  7748> hwp|   Hvi_RequestId = 00001f0000000013
[29.09.2020 08:08:53.995] <  7748> hwp|   Hvi_TimeoutMs = 3600000
[29.09.2020 08:08:53.995] <  7748> hwp|   VmId = da624636-429f-4bc9-b15e-a3de0bc77222
[29.09.2020 08:08:53.995] <  7748> hwp| - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
[29.09.2020 08:08:53.995] <  7748> hwp| Getting VM (ID: da624636-429f-4bc9-b15e-a3de0bc77222) config path.
[29.09.2020 08:08:53.995] <  7748> hwp| Executing wmi query 'SELECT Name, ElementName, __RELPATH FROM Msvm_ComputerSystem WHERE Name = "da624636-429f-4bc9-b15e-a3de0bc77222"'.
[29.09.2020 08:08:54.003] <  7748> hwp| Executing wmi query 'associators of {Msvm_ComputerSystem.CreationClassName="Msvm_ComputerSystem",Name="DA624636-429F-4BC9-B15E-A3DE0BC77222"} where resultClass = Msvm_VirtualSystemSettingData'.
[29.09.2020 08:08:54.179] <  7748> hwp| - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
[29.09.2020 08:08:54.179] <  7748> hwp| Result
[29.09.2020 08:08:54.179] <  7748> hwp|   Hvi_RequestId = 00001f0000000013
[29.09.2020 08:08:54.179] <  7748> hwp|   Hvi_State = Succeeded
[29.09.2020 08:08:54.179] <  7748> hwp|   VmConfigFile = Virtual Machines\DA624636-429F-4BC9-B15E-A3DE0BC77222.VMCX
[29.09.2020 08:08:54.179] <  7748> hwp|   VmConfigFolder = C:\ClusterStorage\Volume1\FSes\FS1
[29.09.2020 08:08:54.179] <  7748> hwp| - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
[29.09.2020 08:08:54.179] <  7748> hwp| Duration: 0.184000 sec
[29.09.2020 08:08:54.193] <  7912> hwp| ---------------------------------------------------------------------------

Видим, что результатом запроса был конфигурационный файл виртуальной машины. Возникает вопрос: почему же для одной машины файл был успешно найден, а для другой нет? Мы знаем, что через несколько минут на ретрае проблемная машина была все же обработана. Идем анализировать ретрай…. (смотрим лог подзадания Task): 

[29.09.2020 08:06:41] <23> Info     [WmiProxy:19node2] HviGetVmInfo: <InputArguments><Hvi_CommitedRequestId__ARRAY><value Val="0000000000000004" /></Hvi_CommitedRequestId__ARRAY><Hvi_LogName value="Critical_FServers\HvWmiProxy-STOREPC-19node2.log" /><Hvi_Host value="STOREPC-19node2" /><Hvi_Process value="00001d98" /><Hvi_RequestId value="0000000000000005" /><Hvi_TimeoutMs value="3600000" /><VmId value="3564c574-8a83-42d2-aef4-46e7218d8ccc" /></InputArguments>

Мы видим, что в этот раз запрос на получение конфигурационного файла машины уже шёл через другую Hyper-V ноду 19node2. Открываем лог HvWmiProxy со второй Hyper-V ноды и видим, что там WMI запрос отработал успешно.

Здесь я предлагаю сделать перерыв, не торопиться читать дальше, а попытаться самому построить теорию. Ведь в детективах самое интересное - это не просто дочитать до конца, а пытаться разгадать еще в середине, а потом просто проверить свои догадки.

2.4 Промежуточные итоги и наконец - теория!

Подводим промежуточные итоги анализа:

  • Запрос валится с пустым значением, когда выполняется на одной Hyper-V ноде, и через несколько минут отрабатывает корректно, когда выполняется на другой Hyper-V ноде.

Напрашивается резонный вопрос – почему на ретрае запрос стал выполняться на второй Hyper-V ноде? Как Veeam определяет, какая нода должна обрабатывать машину? Для обработки машины (создание снапшота и тд.) Veeam выбирает ту ноду, на которой находится машина (owner). В один момент времени у машины может быть только один владелец (owner). Получается, что в момент штатного выполнения машина числилась на одной ноде, а в момент ретрая уже на другой.

А такое вообще возможно?

Дело в том, что если Hyper-V ноды подключены к кластеру, то машины на них могут мигрировать с ноды на ноду в рамках кластера. Происходить это может по абсолютно разным причинам. Здесь можно выдвинуть предположение, что миграция машины с одной Hyper-V ноды на другую служила причиной такого поведения. 

Эту теорию о миграции надо проверять….

 2.5 Проверка теории

Идем смотреть лог самого задания, он же Job лог. Там находим таблицу, в которой прописан список Tasks (подзаданий) для каждой машины:

[29.09.2020 08:03:16] <01> Info     Valid vm tasks ('5'):
[29.09.2020 08:03:16] <01> Info     =================================================================================================================
[29.09.2020 08:03:16] <01> Info     VM                   | Clust. |  Host                     | Size        | Provisioned |  Snapshot Mode| Off-host proxies                                  
[29.09.2020 08:03:16] <01> Info     =================================================================================================================
[29.09.2020 08:03:16] <01> Info     FS1                  | yes    |  19node1                  | 1024 MB     | 4 MB        |        enCrash|                                                   
[29.09.2020 08:03:16] <01> Info     FS2                  | yes    |  19node1                  | 1024 MB     | 4 MB        |        enCrash|                                                   
[29.09.2020 08:03:16] <01> Info     FS3                  | yes    |  19node1                  | 1024 MB     | 4 MB        |        enCrash|                                                   
[29.09.2020 08:03:16] <01> Info     FS4                  | yes    |  19node1                  | 1024 MB     | 4 MB        |        enCrash|                                                   
[29.09.2020 08:03:16] <01> Info     FS5                  | yes    |  19node2                  | 1024 MB     | 4 MB        |        enCrash|

В таблице ясно видно на какой ноде находилась VM во время начала задания. Здесь мы видим, что FS4 была на первой ноде. Смотрим таблицу во время ретрая:

Lifehack: переключаться между выполнениями задания в логе (и штатными, и ретраями) очень удобно, нажав CTRL+f (поиск) и искать “new log”. Таким образом будешь “скакать” от выполнения к выполнению - только не забудь указать, куда хочешь мотать, вперед или назад.

[29.09.2020 08:06:45] <01> Info     Valid vm tasks ('1'):
[29.09.2020 08:06:45] <01> Info     =================================================================================================================
[29.09.2020 08:06:45] <01> Info     VM                   | Clust. |  Host                     | Size        | Provisioned |  Snapshot Mode| Off-host proxies                                  
[29.09.2020 08:06:45] <01> Info     =================================================================================================================
[29.09.2020 08:06:45] <01> Info     FS4                  | yes    |  19node2                  | 1024 MB     | 4 MB        |        enCrash|

Вуа-ля! Мы подтвердили, что машина мигрировала (смена ноды для машины и есть миграция). В случае необходимости можно запросить и глянуть Windows Events с ноды. Нужные события находятся в ветке Hyper-V-VMMS > Admin.

Элементарно, Ватсон!

Следовательно, такую, казалось бы, мистическую ситуацию можно объяснить достаточно просто – во время начала задания Veeam строит список машин, которые нужно будет обработать, и определяет на какой Hyper-V ноде какая машина находится. Когда дело доходит до машины, то обрабатывается именно та Hyper-V нода, на которой она была в момент начала задания.

 В ситуации, когда в задании много машин, и некоторые ждут своей очереди несколько часов, вполне реальна ситуация, что машина мигрирует на другую ноду, и возникнет такая ошибка. На ретрае Veeam опять определяет Hyper-V ноду для машины, и все отрабатывает штатно. Это одна из причин, почему десять мелких бекапных заданий будут лучше, чем одно большое.

Возникает законный вопрос – почему бы не определять Hyper-V ноду для машины прямо перед началом её обработки, чтобы учесть возможность миграции? Дело в том, что такие ограничения связаны с шаренными снапшотами и оптимизациями для параллельной обработки виртуальных машин.

Шаренный снапшот - это когда создается теневая копия на уровне хоста, и в неё добавляются сразу несколько компонентов Hyper-V VSS райтера. Это необходимо, чтобы сделать одну теневую копию волюма, и с этой копии сделать бэкап нескольких виртуальных машин, расположенных на нем. В противном случае для каждой виртуальной машины будет создаваться заново теневая копия всего волюма, на котором расположено несколько машин.

Эти настройки описаны здесь.

Подробнее о том, зачем используется теневая копия (VSS) во время бэкапа, можно почитать здесь.

А сама опция называется - Allow processing of multiple VMs with a single volume snapshot

Таким образом, Veeam в самом начале задания анализирует все виртуальные машины, которые предстоит бэкапить, и в зависимости от разных факторов (например, расположение на одном волюме) может выбирать машины группами. Соответственно, ресурсы планируются в самом начале выполнения задания. И то, что машина мигрировала - это нештатная ситуация, которая успешно отрабатывается на повторе. Поэтому можно сказать, что возникновение такой ошибки - это ожидаемая и подконтрольная ситуация, как бы странно это ни звучало.

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

Автор: Никита Шашков (Veeam), Customer Support Engineer.