[Системное администрирование, Серверное администрирование, Резервное копирование, Софт] Детектив с Кластером Hyper-V: шаг за шагом ищем решение проблемы
Автор
Сообщение
news_bot ®
Стаж: 6 лет 9 месяцев
Сообщений: 27286
Как бы круто это ни звучало - “Логдайвинг” - на самом деле ковыряние логов может быть не самым интересным занятием, а на первых порах даже вызывать фрустрацию (когда файлов куча, но не знаешь, куда смотреть). Но, этот навык очень хорошо развивается с опытом. По кусочку, по крупинке навык развивается, и в очередной раз открывая папку с логами, уже не нервничаешь, а хладнокровно ищешь информацию, зная, куда смотреть.В то же время умение работать с логами - очень ценный и полезный навык. Я бы сравнил работу с логами с поеданием овсянки. Есть овсянку - полезно == уметь анализировать логи - полезно. Ну, а для того, чтобы овсянка стала вкуснее, в нее я добавлю топпинг - интересный сценарий. Чем более загадочной выглядит проблема, тем интереснее становится анализ логов, и ты смотришь уже не просто на строки текста, а распутываешь клубок из улик и доказательств, проверяешь или опровергаешь теории.Ну что, наливаем чаек, сейчас мы будем расследовать - Детектив с Кластером 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.
===========
Источник:
habr.com
===========
Похожие новости:
- [Информационная безопасность, WordPress, Разработка веб-сайтов, Системное администрирование, Контекстная реклама] WordPress автоматически отключит Google FLoC на веб-сайтах
- [IT-инфраструктура, Серверное администрирование, Хранение данных] Большая битва серверов: 'Made in Russia' vs. 'Made in Taiwan'
- [Резервное копирование, Законодательство в IT, Облачные сервисы] Непростой бэкап: строим BaaS-сервис для работы с ПДн и ГИС
- [Системное администрирование, PostgreSQL, Администрирование баз данных] Noisia — генератор аварийных и нештатных ситуаций в PostgreSQL
- [Системное администрирование, Разработка под Windows, Дизайн, Софт] Показания загруженности процессора в диспетчере задач ни о чем на самом деле не говорят (перевод)
- [Софт] Botfather: универсальный фреймворк для автоматизации
- [Разработка под MacOS, Софт, Процессоры] Docker получил поддержку Apple M1
- [Информационная безопасность, Софт] Мониторинг атак
- [Софт, IT-компании] Вебинар “ИТ-вызовы 2021 года: с чем бороться и как эффективно защищать свою сеть”
- [Системное администрирование, Kubernetes] 29 апреля состоится Online Monitoring Meetup, Kubernetes: мониторинг c помощью Prometheus
Теги для поиска: #_sistemnoe_administrirovanie (Системное администрирование), #_servernoe_administrirovanie (Серверное администрирование), #_rezervnoe_kopirovanie (Резервное копирование), #_soft (Софт), #_veeam, #_hyperv, #_blog_kompanii_veeam_software (
Блог компании Veeam Software
), #_sistemnoe_administrirovanie (
Системное администрирование
), #_servernoe_administrirovanie (
Серверное администрирование
), #_rezervnoe_kopirovanie (
Резервное копирование
), #_soft (
Софт
)
Вы не можете начинать темы
Вы не можете отвечать на сообщения
Вы не можете редактировать свои сообщения
Вы не можете удалять свои сообщения
Вы не можете голосовать в опросах
Вы не можете прикреплять файлы к сообщениям
Вы не можете скачивать файлы
Текущее время: 22-Ноя 03:15
Часовой пояс: UTC + 5
Автор | Сообщение |
---|---|
news_bot ®
Стаж: 6 лет 9 месяцев |
|
Как бы круто это ни звучало - “Логдайвинг” - на самом деле ковыряние логов может быть не самым интересным занятием, а на первых порах даже вызывать фрустрацию (когда файлов куча, но не знаешь, куда смотреть). Но, этот навык очень хорошо развивается с опытом. По кусочку, по крупинке навык развивается, и в очередной раз открывая папку с логами, уже не нервничаешь, а хладнокровно ищешь информацию, зная, куда смотреть.В то же время умение работать с логами - очень ценный и полезный навык. Я бы сравнил работу с логами с поеданием овсянки. Есть овсянку - полезно == уметь анализировать логи - полезно. Ну, а для того, чтобы овсянка стала вкуснее, в нее я добавлю топпинг - интересный сценарий. Чем более загадочной выглядит проблема, тем интереснее становится анализ логов, и ты смотришь уже не просто на строки текста, а распутываешь клубок из улик и доказательств, проверяешь или опровергаешь теории.Ну что, наливаем чаек, сейчас мы будем расследовать - Детектив с Кластером Hyper-V Дисклеймер: я привожу пример того, как я анализирую логи. Жесткого стандарта нет, и действия других инженеров техподдержки Veeam могут (и будут) отличаться. Скриншоты и логи взяты из моей лабы, так как логи клиентов никогда не публикуются и удаляются при закрытии кейса.
Когда есть конкретная ошибка, это уже хорошо. Сразу понятно: что-то явно сломано – это как стук в двигателе машины. Мы видим, что это ошибка в работе 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. Анализ собранной информации Итак, распаковали архив и видим следующее:
Хммм, с чего же начать…..А начинать, я считаю, надо от общего к частному. Общим в нашем случае будет HTML отчет - так как в нем мы видим общую информацию о выполнении задания за период времени, и можно прикинуть статистику. Ну и, конечно же, отчет более приятен человеческому глазу, чем сотни строк логов =)2.1 Отчет задания, и зачем его смотреть Смотреть отчет очень удобно, чтобы представить общую картину и определиться с дальнейшими шагами. В нём мы пытаемся найти закономерности, такие, как данные по определенной проблемной машине или по нескольким определенным машинам, либо же даты выполнения задания. В общем, пытаемся прицепиться к чему-то, чтобы дальше проверять, связано ли это с конкретной машиной, конкретным хостом, конкретным хранилищем или конкретным временем. Что же мы видим в отчете?
В этой папке для задания резервного копирования можно встретить 3 типа логов:
[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) Host value="STOREPC-19node1"
LogName value="Critical_FServers\HvWmiProxy-STOREPC-19node1.log И находим лог компонента, отвечающего за 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| --------------------------------------------------------------------------- [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>
[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| 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| =========== Источник: habr.com =========== Похожие новости:
Блог компании Veeam Software ), #_sistemnoe_administrirovanie ( Системное администрирование ), #_servernoe_administrirovanie ( Серверное администрирование ), #_rezervnoe_kopirovanie ( Резервное копирование ), #_soft ( Софт ) |
|
Вы не можете начинать темы
Вы не можете отвечать на сообщения
Вы не можете редактировать свои сообщения
Вы не можете удалять свои сообщения
Вы не можете голосовать в опросах
Вы не можете прикреплять файлы к сообщениям
Вы не можете скачивать файлы
Вы не можете отвечать на сообщения
Вы не можете редактировать свои сообщения
Вы не можете удалять свои сообщения
Вы не можете голосовать в опросах
Вы не можете прикреплять файлы к сообщениям
Вы не можете скачивать файлы
Текущее время: 22-Ноя 03:15
Часовой пояс: UTC + 5