Как бы круто это ни звучало - Логдайвинг - на самом деле ковыряние логов может быть не самым интересным занятием, а на первых порах даже вызывать фрустрацию (когда файлов куча, но не знаешь, куда смотреть). Но, этот навык очень хорошо развивается с опытом. По кусочку, по крупинке навык развивается, и в очередной раз открывая папку с логами, уже не нервничаешь, а хладнокровно ищешь информацию, зная, куда смотреть.
В то же время умение работать с логами - очень ценный и полезный навык. Я бы сравнил работу с логами с поеданием овсянки. Есть овсянку - полезно == уметь анализировать логи - полезно. Ну, а для того, чтобы овсянка стала вкуснее, в нее я добавлю топпинг - интересный сценарий. Чем более загадочной выглядит проблема, тем интереснее становится анализ логов, и ты смотришь уже не просто на строки текста, а распутываешь клубок из улик и доказательств, проверяешь или опровергаешь теории.
Ну что, наливаем чаек, сейчас мы будем расследовать - Детектив с Кластером 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 есть встроенный помощник для таких дел. Есть даже статья с анимацией - https://www.veeam.com/kb1832 Поэтому, в консоли 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 Отчет задания, и зачем его смотреть
Смотреть отчет очень удобно, чтобы представить общую картину и определиться с дальнейшими шагами. В нём мы пытаемся найти закономерности, такие, как данные по определенной проблемной машине или по нескольким определенным машинам, либо же даты выполнения задания. В общем, пытаемся прицепиться к чему-то, чтобы дальше проверять, связано ли это с конкретной машиной, конкретным хостом, конкретным хранилищем или конкретным временем.
Что же мы видим в отчете?
-
Сервер FS4 падает с ошибкой;
-
Через несколько минут - успешный Retry для сервера FS4
-
Во время следующего штатного выполнения задания серверы FS2 и FS3 падают с этой же WMI-ошибкой
-
Через несколько минут - успешный Retry для серверов FS2 и FS3
Вывод по анализу отчета: Из нашего списка машин при штатном выполнении задания некоторые падают, но обязательно отрабатывают с ретрая буквально через несколько минут. Установить закономерность падения машин невозможно, они падают рандомно. Также бывают абсолютно успешные штатные выполнения задания для всех машин.
Retry - специальная настройка задания, которая попытается повторить его выполнение только для тех VM, для которых не был создан бэкап. В настройках задания обычно указывается, сколько раз пробовать Retry и через какой промежуток времени после неудачи.
Теории о том, что:
-
есть проблемная машина или ряд проблемных машин;
-
есть проблемная Hyper-V нода ;
отпадают, так как почти все машины из списка хоть раз да падали. После анализа отчета, не имея чёткой теории, что именно надо проверять дальше, я иду смотреть полный стек ошибки, так как в репорт выведена только одна строка, и необходимо увидеть контекст, в котором она появилась.
2.2 Логи задания: ищем стэк ошибки
Так как ошибка одна, но появляется для разных машин, то мы просто выбираем любое выполнение задания с ошибкой и анализируем его. Для начала идем в лог, который описывает обработку конкретной машины в задании - той, для которой вышла ошибка. Схема, по которой ищутся логи для задания - Veeam сервер\Backup\Название задания. В нашем случае это storepc.dom1.loc\Backup\Critical_FServers. Более подробно про структуру логов и где что лежит мы писали в отдельных статьях здесь и здесь.
В этой папке для задания резервного копирования можно встретить 3 типа логов:
-
Agent - логи компонента, который занимается передачей данных (Veeam Agent - Data mover). Если в названии есть слово Target, значит - это лог агента, который записывал данные на репозиторий. Если это задание репликации, то Target будет в папке на сервере, который использовался в качестве целевого прокси и писал данные на хранилище данных гипервизора (Datastore) куда реплицируем. Если в названии есть слово Source, значит - это лог агента, который читал данные с хранилища данных гипервизора (Datastore).
-
Job - это лог задания целиком. При общении с сапортом можно смело говорить просто джоба, и вас поймут.
-
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 райтера. Это необходимо, чтобы сделать одну теневую копию волюма, и с этой копии сделать бэкап нескольких виртуальных машин, расположенных на нем. В противном случае для каждой виртуальной машины будет создаваться заново теневая копия всего волюма, на котором расположено несколько машин.
Эти настройки описаны здесь - https://helpcenter.veeam.com/docs/backup/hyperv/backup_job_advanced_hv_hv.html?ver=100
Подробнее о том, зачем используется теневая копия (VSS) во время бэкапа, можно почитать здесь - https://helpcenter.veeam.com/docs/backup/hyperv/online_backup.html?ver=100#2012r2
А сама опция называется - Allow processing of multiple VMs with a single volume snapshot
Таким образом, Veeam в самом начале задания анализирует все виртуальные машины, которые предстоит бэкапить, и в зависимости от разных факторов (например, расположение на одном волюме) может выбирать машины группами. Соответственно, ресурсы планируются в самом начале выполнения задания. И то, что машина мигрировала - это нештатная ситуация, которая успешно отрабатывается на повторе. Поэтому можно сказать, что возникновение такой ошибки - это ожидаемая и подконтрольная ситуация, как бы странно это ни звучало.
Кроме того, миграция машины может произойти в момент подготовки снапшота, то есть когда ресурсы уже запланированы и определился список машин для снапшота. От этого сложно застраховаться, разве что изменить кластерную политику на распределение машин по хостам. Но, возможно, в один прекрасный день наши крутые разработчики найдут решение и для этого нюанса удивительного мира виртуальных машин.
Автор: Никита Шашков (Veeam), Customer Support Engineer.
