Учимся читать логи ваших бекапов

Скажите честно, в своей практике вам чаще приходилось сталкиваться с логами, напоминающими чей-то поток сознания, или всё же это были красивые структурированные файлы, на которые любо-дорого смотреть? Надеюсь, что второе. В наших продуктах, само собой, мы тоже стремимся идти по второму пути, однако необходимость зафиксировать большое количество процессов накладывает свой отпечаток. Так что сегодня мы научимся не “читать книгу и видеть фигу”, а бесстрашно открывать любой лог Veeam Backup & Replication и видеть его внутреннюю красоту.

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

Когда читаешь логи, очень важно держать в голове и применять шесть простых правил.

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

// Виму надо отключиться от vCenter:
[19.10.2020 05:02:53] <01> Info  [Soap] Logout from "https://vcenter.test.local:443/sdk"

// Убеждаемся, что мы действительно отключились, попробовав выполнить любое действие. Получить ошибку здесь — ожидаемый результат.
[19.10.2020 05:02:53] <01> Error The session is not authenticated. (System.Web.Services.Protocols.SoapException)
[19.10.2020 05:02:53] <01> Error at System.Web.Services.Protocols.SoapHttpClientProtocol.ReadResponse(SoapClientMessage message, WebResponse response, Stream responseStream, Boolean asyncCall)

Правило второе: Когда читаете лог, не надо смотреть только на последнюю в списке ошибку. Даже если она подсвечена в репорте, упавшем на почту. Причина её появления запросто может быть на пару экранов (и десяток других ошибок) выше. Например, в упавшем на почту HTML репорте видим ошибку "Microsoft SQL server hosting the configuration database is currently unavailable". Открываем лог джобы и видим, что последняя ошибка в логе прямо нам говорит “Не могу подключиться к SQL серверу, потому что <причины>”.

[12.11.2019 23:24:00] <18> Error Microsoft SQL server hosting the configuration database is currently unavailable. Possible reasons are heavy load, networking issue, server reboot, or hot backup.
[12.11.2019 23:24:00] <18> Error Please wait, and try again later.

Сразу хочется победно прокричать “Ага!” и побежать чинить связь до SQL сервера, перезагружать его, трясти за бампер и пинать по колесу. Однако если попробовать разобраться и отмотать лог ближе к началу, там обнаруживаются строки:

12.11.2019 23:22:00] <18> Error Violation of PRIMARY KEY constraint 'PK_Storages'. Cannot insert duplicate key in object 'dbo.Backup.Model.Storages'. The duplicate key value is (af4d30aa-9605-4fe6-8229-f362eb848f19).
[12.11.2019 23:22:00] <18> Error Violation of PRIMARY KEY constraint 'PK_Storages'. Cannot insert duplicate key in object 'dbo.Backup.Model.Storages'. The duplicate key value is (af4d30aa-9605-4fe6-8229-f362eb848f19).

Из чего сразу становится понятно, что со связью до базы всё хорошо — а вот что плохо, так это то, что VBR не может выполнить какую-то кверю, и копать надо в эту сторону.

Правило третье: Редкая ошибка локализуется внутри одного конкретного лога. Изучение соседних логов на тот же момент времени позволяет собрать намного больше информации. Хрестоматийный пример — это лог джобы, где нам просто говорят, что возникала такая-то ошибка в такой-то таске. Какие-то выводы, конечно, мы сделать уже можем, но лучше открыть лог таски и получить более подробное описание случившегося бедствия. И если уж совсем ничего не понятно, то нам на помощь приходят логи агентов, в которых вся ситуация будет разобрана крайне подробно. Но тут действует правило “Чем дальше в лес, тем более узким и специфичным становится лог”. А ещё часть инфы может всплыть в сервисных логах, часть в виндовых ивентах и так далее.

Вот, например, берём типичный лог упавшей джобы:

[13.06.2019 11:06:07] <52> Error  Failed to call RPC function 'CreateSessionTicket': Agent with the specified identifier '{c8fdc9b9-0d60-486c-80de-9fc4218d276f}' does not exist

Типичный никчёмный Failed to call RPC function, из которого максимум, что можно понять — что не удалось провзаимодействовать с транспортным агентом. Однако если вспомнить, что транспортный агент управляется транспортным сервисом (известен в документации как Datamover) и заглянуть в его лог (Svc.VeeamTransport.log) на хосте, где он запускался, то можно обнаружить:

[13.06.2019 09:05:07] < 10648> tpl|   Agent '{c8fdc9b9-0d60-486c-80de-9fc4218d276f}' will be terminated due to reason: some I/O operation has hanged.
[13.06.2019 09:06:07] < 10648> tpl| WARN|AGENT [{c8fdc9b9-0d60-486c-80de-9fc4218d276f}] HAS HANGED UNEXPECTEDLY AND WAS TERMINATED.

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

Правило четвёртое: Если в логах видим, что ошибка происходит где-то за границами компонентов VBR, значит, искать их причину надо тоже за границами компонентов VBR. Veeam хоть и старательно логирует все приходящие к нему события, однако ещё больше их(событий) остаётся на целевой системе. Типичным примером здесь будет создание VSS снапшота. По большому счёту, Windows отдаёт информацию на уровне “получилось или нет что-то сделать”, из чего крайне редко получается вычленить причину, почему же не получилось. Однако внутри виндовых ивентов можно найти множество событий, прямо указывающих на проблему. Главное — всегда тщательно сопоставлять время в логах от разных систем. Помним, что у VBR своё время, у vSphere всегда UTC+0, а виндовые ивенты показываются в локальном времени машины, на которой их смотрят. Типичные примеры экспорта внешних логов — для Windows и для Microsoft SQL.

Правило пятое: Следи за тредами (они обозначаются как <XX>) и распутывай клубок последовательно! Многие вещи могут происходить параллельно, и если просто читать логи линия за линией, то можно прийти к неправильному выводу. Особенно это важно, если джоба кажется зависшей и надо понять, что именно в ней зависло.

 Вот типичный лог для этой ситуации:

[18.06.2020 03:44:03] <36> Info [AP] Waiting for completion. Id: [0xf48cca], Time: 00:30:00.0333386
[18.06.2020 03:45:18] <53> Info [AP] (6ff9) output: --asyncNtf:Pipeline timeout: it seems that pipeline hanged.

Если читать это лог, не обращая внимания на номера тредов <36> и <53>, то кажется, что у нас какие-то проблемы с агентом 6ff9, и надо срочно разбираться, что с ним случилось. Однако если продолжить чтение лога с оглядкой на тред <36>, то обнаруживается, что:

[18.06.2020 03:14:03] <36> Info  [AP] (bf19) command: 'Invoke: DataTransfer.SyncDisk…

То есть этот тред посвящён совершенно другому агенту с id bf19! Открываем лог этого агента и видим:

[17.06.2020 12:41:23] <  2160>  ERR |Data error (cyclic redundancy check).
[17.06.2020 12:41:23] <  2160>  >>  |Failed to read data from the file [E:\Hyper-V\VHDs\SRV-DCFS02\SRV-DCFS02-C.vhdx].

 Значит, проблема в битом VHDX и надо искать методы его лечения.

Правило шестое: Не получается, непонятно, кажется, что вот-вот, но идёт третий день без сна и всё никак — звони в сапорт! Veeam — огромный продукт, где есть тысячи нюансов, нюансы для нюансов и прочих сокровенных знаний, которые никогда не понадобятся 99,99% населения этой планеты. Однако именно этих знаний в большинстве случаев и не хватает, чтобы успешно найти причину неисправности самому. Сапорт Вима совсем не просто так получает свою зарплату и считается одним из лучших в IT-индустрии. А ещё он русскоязычный и доступен по телефону ;)

Смело открываем лог

И вот настал тот прекрасный момент, когда мы наконец-то готовы открыть свой первый лог. А любой уважающий себя файл начинается с некоего заголовка, где собрана вся основная информация. Чаще всего нас, конечно же, будут интересовать логи джоб и тасок, так что рассмотрим пример с ними.

===================================================================
Starting new log
Log has been started by 'VEEAM\SYSTEM' user (Non-interactive)
Logging level: [4 (AboveNormal)]
MachineName: [VEEAM], OS: [Microsoft Windows Server 2019 Standard (10.0.17763)], CPU: [2]
Process: [64 bit], PID: [10816], SessionId: [0]
UTC Time: [22.10.2020 2:03:53], DaylightSavingTime: [False]
Culture: [ru-RU], UI culture: [en-US]
Module: [C:\Program Files\Veeam\Backup and Replication\Backup\Veeam.Backup.Manager.exe]. File version: [10.0.1.4854], Assembly version: [10.0.0.0], Edition: [standard]
Process start time: [22.10.2020 0:01:19], Garbage collector mode: [Workstation]
CmdLineParams: [startbackupjob owner=[vbsvc] Normal bed49ecd-54a4-4f53-b337-e71fabe92988 44c3f481-66ec-475f-bd04-a321e69274a0]
Network Interface, Name: Ethernet0, Description: Intel(R) 82574L Gigabit Network Connection, Interface Type: Ethernet, Operational Status: Up;
	Unicast IPAddresses: fe80::b99c:9c8a:6179:295b%6; 172.17.32.51;
	Gateway IPAddresses: 172.17.32.1;
Network Interface, Name: Loopback Pseudo-Interface 1, Description: Software Loopback Interface 1, Interface Type: Loopback, Operational Status: Up;
	Unicast IPAddresses: ::1; 127.0.0.1;
UTC offset: 3,00 hours

Начало не вызывает никаких особых вопросов. Мы видим, как называется машина, на которой установлен VBR, и под каким пользователем запускается Veeam Backup Service.

Log has been started by 'VEEAM\SYSTEM' user (Non-interactive)
MachineName: [VEEAM], OS: [Microsoft Windows Server 2019 Standard (10.0.17763)],

Важный пункт — это версия запускающегося модуля.

Module: [C:\Program Files\Veeam\Backup and Replication\Backup\Veeam.Backup.Manager.exe]. File version: [10.0.1.4854], Assembly version: [10.0.0.0], Edition: [standard]

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

Затем идёт перечисление всех сетевых интерфейсов и их IP-адреса. Также по названию карты зачастую можно понять, стоит ли Veeam на виртуальной машине или на физической. Хотя вы и сами наверняка это знаете, но может пригодиться.

Network Interface, Name: Ethernet0, Description: Intel(R) 82574L Gigabit Network Connection, Interface Type: Ethernet, Operational Status: Up;
	Unicast IPAddresses: fe80::b99c:9c8a:6179:295b%6; 172.17.32.51;
	Gateway IPAddresses: 172.17.32.1;
Network Interface, Name: Loopback Pseudo-Interface 1, Description: Software Loopback Interface 1, Interface Type: Loopback, Operational Status: Up;
	Unicast IPAddresses: ::1; 127.0.0.1;

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

UTC Time: [22.10.2020 2:03:53], DaylightSavingTime: [False]
UTC offset: 3,00 hours

Теперь, когда заголовок прочитан, давайте на примере бекапа и реплики посмотрим, что нас ожидает в логе любой джобы. Я не буду объяснять каждую строчку, иначе мы отсюда через месяц только разойдёмся. Просто легкая пробежка по общему принципу.

• Первым делом джоба должна перечитать свои собственные настройки, дабы вообще знать, что ей требуется сделать.

• Затем формируется список объектов, участвующих в бекапе.

• Для всех объектов надо заблокировать необходимые ресурсы (файлы с бекапами, например) и убедиться, что никто другой не пытается с ними работать в этот момент времени.

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

• После чего можно запускать отдельные таски и ждать отчёта об их успешном (хочется верить, что да) выполнении.

• И в конце, когда все таски отчитались, наступает тяжелая пора проверки ретеншенов. Удаляются старые точки, запускаются синтетические трансформы и прочий страшный сон для ваших СХД.

• Когда всё закончилось успехом, надо везде рапортовать про это, записать в базу новую информацию и счастливо заснуть до следующего запуска. Конечно, строго говоря, на фоне будет происходить масса разнообразных и увлекательных сервисных вещей, но сегодня не об этом.

Теперь давайте обратим внимание на таски. Каждая таска запускается с чётко поставленной целью забекапить конкретную машину. Значит, после запуска её дело — это суметь подключиться к хосту, запустить агентов (в документации известны как data movers), проверить, что есть связь между компонентами, и совершить процесс передачи информации от хранилища вашего хоста до бекапного репозитория с необходимыми трансформациями по пути. Сжатие, разжатие, дедупликация, шифрование и так далее.

Соответственно, начинаем поиски проблемы широкими мазками, а именно — выясняем, на каком моменте всё сломалось. В этом нам помогает волшебное словосочетание has been completed. В общем случае таски рапортуют таким образом:

[19.10.2020 05:02:44] <29> Info Task session [3af0e723-b2a3-4054-b4e3-eea364041402] has been completed, status: Success, 107,374,182,400 of 107,374,182,400 bytes, 55,326,015,488 of 55,326,015,488 used bytes, 14 of 14 objects, details:

14 объектов — это так называемые OiB, Object in Backup. Эта информация дублируется в логе джобы после завершения каждой таски с пометкой о том, сколько тасок уже завершилось. А в самом конце джоба должна заканчиваться полным отчётом.

[19.10.2020 05:02:53] <01> Info Job session '0f8ad58b-4183-4500-9e49-cc94f0674d87' has been completed, status: 'Success', '100 GB' of '100 GB' bytes, '1' of '1' tasks, '1' successful, '0' failed, details: '', PointId: [d3e21f72-9a52-4dc9-bcbe-98d38498a3e8]

Другая полезная фраза — это Preparing point. Позволяет нам понять, какой тип бекапа сейчас будет создаваться.

В случае создания полного бекапа, в народе именуемого фульник (Full или Active full), создаётся следующая запись:

[17.11.2019 22:01:28] <01> Info Preparing point in full mode 

Инкрементальный проход выглядит вот так:

[17.11.2019 22:01:28] <01> Info Preparing point in incremental mode 

И реверс инкремент:

[17.11.2019 22:01:28] <01> Info Preparing point in synthetic mode 

Для Synthetic full своей особой записи не существует! Она начинает с создания обычного инкремента, поэтому надо искать ниже в логе запись "Creating synthetic full backup". Или пройтись по "Preparing oib" в логе таски.

vSphere

Теперь переходим к специфике гипервизоров, ибо, как можно легко догадаться, VMware и Hyper-V под капотом устроены даже приблизительно не одинаково, так что и работать с ними надо по-разному.

И начнём мы именно с VMware. Для начала просто посмотрим версию хоста по слову Build- в логе джобы. Так мы сможем узнать версию и номер билда хоста с машиной. Если хост был добавлен как часть Vcenter, бонусом получаем поле source host type.

[01.11.2020 05:00:26] <01> Info VM task VM name: 'vudc01', VM host name: 'https://esxi.test.local', VM host info: 'VMware ESXi 6.5.0 build-16207673', VM host apiVersion: '6.5', source host name: 'vcenter.test.local', source host id: '3de6c11c-ad7e-4ec0-ba12-d99a0b30b493', source host type: 'VC', size: '107374182400', display name: 'vudc01'.

Эта же информация дублируется в момент проверки доступных режимов работы прокси.

[01.11.2020 05:00:24] <01> Info [ProxyDetector] Proxy [dsg.test.local] lies in different subnet with host [VMware ESXi 6.5.0 build-16207673]

В логе соответствующей таски это всё тоже имеется, только там это часть здоровенной XML, так что копипастить я её не буду. Зато там есть даже более интересная строка Host content info:

[01.11.2020 05:01:37] <37> Info  [Soap] Host content info: host "vcenter.test.local", type "vpx", version "6.5.0", build "15259038", apiVersion "6.5", hostTime "01.11.2020 2:01:26", sessionKey: "52c2dbf9-1835-2eb3-bb0e-396166a8101f"

Там же, в логе таски, можно получить информацию о дисках и датасторах по строке Disk: label

[07.08.2019 06:55:41] <82> Info Disk: label "Hard disk 1", path "[ALLIN_PURE_GDI] LXRP-IT-GPILDB1/LXRP-IT-GPILDB1_21.vmdk", capacity 25,0 GB, backing "CFlatVirtualDiskV2", mode "persistent", thinProvisioned "False"

Как мы видим, нас интересует ALLIN_PURE_GDI, поэтому переключаемся на лог джобы и видим:

[12.08.2019 05:40:12] <01> Info [ProxyDetector] Datastore 'ALLIN_PURE_GDI' lun was found, it uses vmfs

или

[12.08.2019 05:40:12] <01> Info [ProxyDetector] Datastore 'ALLIN_PURE_GDI' lun was found, it uses nas

Ещё бывает "Backup VM 'VMname' is DirectNFS compatible", но это не значит, что наша машина точно на NFS шаре.

Жизненный цикл vSpehere снапшотов

…и места, где они обитают.

Часто (а на самом деле практически всегда) понимать, в какой момент создавался снапшот, в какой был удалён и что с ним происходило, весьма важно для получения целостной картины мира реплик и бекапов. Поэтому открываем лог таски и ищем в нём API вызовы для создания и консолидации (удаления) снапшотов. Создание снапшота отлично ищется по Create snapshot

[02.11.2020 05:01:09] <29> Info [VimApi] Create snapshot, ref "vm-26", name "VEEAM BACKUP TEMPORARY SNAPSHOT", description "Please do not delete this snapshot. It is being used by Veeam Backup.", memory "False", quiesce "False"
[02.11.2020 05:01:11] <29> Info [Soap] Snapshot VM 'vm-26' was created. Ref: 'snapshot-540'

Удаление снапшота ищется по Removing snapshot.

[01.11.2020 05:02:30] <26> Info [Soap] Removing snapshot 'snapshot-536'
[01.11.2020 05:02:30] <26> Info [VimApi] RemoveSnapshot, type "VirtualMachineSnapshot", ref "snapshot-536", removeChildren "False"
[01.11.2020 05:02:32] <26> Info [VmSnapshotTracker] Snapshot id: 'snapshot-536' closed
[01.11.2020 05:02:32] <26> Info [Soap] Loaded 2 elements
[01.11.2020 05:02:32] <26> Info [ViSnapshot] Checking if disks consolidation is needed for vm 'vm-26'
[01.11.2020 05:02:32] <26> Info [ViSnapshot] Consolidation is not needed

Здесь что хочется отметить: по загадочной причине в логе VMware.log зачастую нет никакой информации об ошибках произошедших во время создания/удаления снапшота. Поэтому полную картину мира надо восстанавливать по всем логам vSphere, включая логи VPXD и HOSTD.

С точки зрения vSphere, в VMware.log обычно есть только события на создание снапшота:

2019-05-24T13:58:57.921Z| vmx| I125: SnapshotVMX_TakeSnapshot start: 'VEEAM BACKUP TEMPORARY SNAPSHOT', deviceState=0, lazy=0, quiesced=0, forceNative=0, tryNative=1, saveAllocMaps=0 cb=35DE089A0, cbData=35F700420 
....
2019-05-24T13:59:01.111Z| vcpu-0| I125: VigorTransport_ServerSendResponse opID=a9e2725d-8d3e-41c3-bea7-40d55d4d13fe-3088830-h5c:70160745-a8-af-3321 seq=187319: Completed Snapshot request. 

И на удаление:

2019-05-24T13:59:31.878Z| vmx| I125: SNAPSHOT: SnapshotDeleteWork '/vmfs/volumes/5b0c32e4-3bc067bb-614b-f4e9d4a8b220/test_build/test_build.vmx' : 29
....
2019-05-24T13:59:35.411Z| vcpu-0| I125: ConsolidateEnd: Snapshot consolidate complete: The operation completed successfully (0).

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

Зато как только мы заводим разговор о репликах, всё становится ещё веселее. VMware.log ведётся только когда виртуалка работает. А для реплицированных машин нормальное состояние — быть выключенными. Так что этот лог вам никак помочь не может. Поэтому здесь нам понадобятся логи vCenter или хоста. Самый простой способ их добыть — это ПКМ на vCenter > Export System Logs. В открывшемся визарде обязательно выбираем "Include vCenter server logs" и дожидаемся скачивания результата. Логи влёгкую могут весить несколько гигабайт, а скачиваться будут через браузер. Так что советую делать это на машине максимально близкой к VC. Самое интересное для нас внутри, это:

• ESXi: В архиве проходим по /var/run/log/ и находим hotsd.log. Рядом будут лежать упакованные более ранние версии.

• VC: ищем файлы vpxd-xxx.log по пути /var/log/vmware/vpxd. 

Теперь давайте сравним, как будут выглядеть записи об одних и тех же операция в логе VBR, логе vpxd, и логе hostd. Здесь мы опустим моменты создания снапшота на исходной машине, так как нас интересует только реплика.

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

//Veeam Task log:
[19.05.2020 18:41:04] <20> Info [SnapReplicaVm] Find working snapshots for replica vm '[name 'TinyLinux2_replica', ref 'vm-3411']'
[19.05.2020 18:41:04] <20> Info [SnapReplicaVm] Reverting vm '[name 'TinyLinux2_replica', ref 'vm-3411']' to restore point '5/19/2020 15:37:13'
[19.05.2020 18:41:04] <20> Info [Soap] Reverting snapshot snapshot-3415
[19.05.2020 18:41:04] <20> Info [VimApi] RevertSnapshot, type "VirtualMachineSnapshot", ref "snapshot-3415"

//VPXD:
2020-05-19T15:41:00.508Z info vpxd[04767] [Originator@6876 sub=vpxLro opID=7717265a] [VpxLRO] -- BEGIN task-32169 -- snapshot-3415 -- vim.vm.Snapshot.revert -- 52e02fc8-9bbb-74da-63ac-74879274c5a3(52e50ab9-39d5-0996-21ce-3877ead7a6e9)

//Hostd:
2020-05-19T15:41:00.492Z info hostd[2099911] [Originator@6876 sub=Vimsvc.TaskManager opID=7717265a-a1-62d8 user=vpxuser:VSPHERE.LOCAL\Administrator] Task Created : haTask-676-vim.vm.Snapshot.revert-5370407
2020-05-19T15:41:00.652Z info hostd[2099895] [Originator@6876 sub=Vimsvc.TaskManager opID=7717265a-a1-62d8 user=vpxuser:VSPHERE.LOCAL\Administrator] Task Completed : haTask-676-vim.vm.Snapshot.revert-5370407 Status success

После успешного отката (двусмысленные фразы, что вы делаете, аха-ха-ха, прекратите) нам надо зафиксировать успех, т.е. сделать текущую дельту доступной только для чтения. Для этого создаём ещё один снапшот сверху:

//Veeam Task log:
[19.05.2020 18:41:17] <20> Info [SnapReplicaVmTarget] Creating working snapshot
[19.05.2020 18:41:17] <20> Info [SnapReplicaVm] Creating working snapshot for replica vm '[name 'TinyLinux2_replica', ref 'vm-3411']'
[19.05.2020 18:41:19] <20> Info [VimApi] Create snapshot, ref "vm-3411", name "Veeam Replica Working Snapshot", description "<RPData PointTime="5249033617402408751" WorkingSnapshotTime="5249033617402408751" PointSize="0" PointType="EWorkingSnapshot" DescriptorType="Default" />", memory "False", quiesce "False"
[19.05.2020 18:41:21] <20> Info [Soap] Snapshot VM 'vm-3411' was created. Ref: 'snapshot-3416'

//VPXD:
2020-05-19T15:41:15.469Z info vpxd[00941] [Originator@6876 sub=vpxLro opID=32de210d] [VpxLRO] -- BEGIN task-32174 -- vm-3411 -- vim.VirtualMachine.createSnapshot -- 52e02fc8-9bbb-74da-63ac-74879274c5a3(52e50ab9-39d5-0996-21ce-3877ead7a6e9)

//Hostd:
2020-05-19T15:41:15.453Z info hostd[2099906] [Originator@6876 sub=Vimsvc.TaskManager opID=32de210d-b7-635b user=vpxuser:VSPHERE.LOCAL\Administrator] Task Created : haTask-676-vim.VirtualMachine.createSnapshot-5370436
2020-05-19T15:41:15.664Z info hostd[2099914] [Originator@6876 sub=Vimsvc.TaskManager] Task Completed : haTask-676-vim.VirtualMachine.createSnapshot-5370436 Status success

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

//Veeam Task log:
[19.05.2020 18:41:44] <20> Info [Soap] Reverting snapshot snapshot-3416
[19.05.2020 18:41:44] <20> Info [VimApi] RevertSnapshot, type "VirtualMachineSnapshot", ref "snapshot-3416"
[19.05.2020 18:41:46] <20> Info [Soap] Removing snapshot 'snapshot-3416'
[19.05.2020 18:41:46] <20> Info [VimApi] RemoveSnapshot, type "VirtualMachineSnapshot", ref "snapshot-3416", removeChildren "False

//VPXD:
2020-05-19T15:41:40.571Z info vpxd[22153] [Originator@6876 sub=vpxLro opID=15fb90d9] [VpxLRO] -- BEGIN task-32176 -- snapshot-3416 -- vim.vm.Snapshot.revert -- 52e02fc8-9bbb-74da-63ac-74879274c5a3(52e50ab9-39d5-0996-21ce-3877ead7a6e9)
2020-05-19T15:41:42.758Z info vpxd[17341] [Originator@6876 sub=vpxLro opID=1b7624e9] [VpxLRO] -- BEGIN task-32177 -- snapshot-3416 -- vim.vm.Snapshot.remove -- 52e02fc8-9bbb-74da-63ac-74879274c5a3(52e50ab9-39d5-0996-21ce-3877ead7a6e9)

//Hostd:
2020-05-19T15:41:40.966Z info hostd[2099914] [Originator@6876 sub=Vimsvc.TaskManager opID=15fb90d9-ad-6417 user=vpxuser:VSPHERE.LOCAL\Administrator] Task Completed : haTask-676-vim.vm.Snapshot.revert-5370516 Status success
2020-05-19T15:41:42.764Z info hostd[6710321] [Originator@6876 sub=Vimsvc.TaskManager opID=1b7624e9-89-6435 user=vpxuser:VSPHERE.LOCAL\Administrator] Task Created : haTask-676-vim.vm.Snapshot.remove-5370522
2020-05-19T15:41:42.995Z info hostd[2099912] [Originator@6876 sub=Vimsvc.TaskManager] Task Completed : haTask-676-vim.vm.Snapshot.remove-5370522 Status success

Но поскольку свято место пусто не бывает, сразу после удаления этого снапшота надо создать новый, который возьмёт на себя ответственность называться “Restore Point”. Хотя фактически он служит той же цели — запрещает изменять предыдущую дельту, где лежат данные с боевой машины.

//Veeam Task log:
[19.05.2020 18:41:51] <20> Info [VimApi] Create snapshot, ref "vm-3411", name "Restore Point 5-19-2020 18:40:53", description "<RPData PointTime="5248941014961933064" WorkingSnapshotTime="5249033617402408751" PointSize="64" PointType="ECompleteRestorePoint" DescriptorType="Default" />", memory "False", quiesce "False"
[19.05.2020 18:41:53] <20> Info [Soap] Snapshot VM 'vm-3411' was created. Ref: 'snapshot-3417'

//VPXD:
2020-05-19T15:41:47.170Z info vpxd[48063] [Originator@6876 sub=vpxLro opID=5cc1af26] [VpxLRO] -- BEGIN task-32179 -- vm-3411 -- vim.VirtualMachine.createSnapshot -- 52e02fc8-9bbb-74da-63ac-74879274c5a3(52e50ab9-39d5-0996-21ce-3877ead7a6e9)

//Hostd:
2020-05-19T15:41:47.155Z info hostd[2099311] [Originator@6876 sub=Vimsvc.TaskManager opID=5cc1af26-f3-646c user=vpxuser:VSPHERE.LOCAL\Administrator] Task Created : haTask-676-vim.VirtualMachine.createSnapshot-5370539
2020-05-19T15:41:47.303Z info hostd[2099419] [Originator@6876 sub=Vimsvc.TaskManager] Task Completed : haTask-676-vim.VirtualMachine.createSnapshot-5370539 Status success

И обязательный десерт — применение ретеншн политики. В общем случае это слияние базового диска и самой старой дельты. Только учтите, что эта информация отображается уже в логе джобы, а не таски.

//Veeam Job Log:
[19.05.2020 18:42:21] <49> Info [SnapReplicaVm] DeleteRestorePoint 'PointTime: 5/19/2020 15:33:10, DigestStorageTimeStamp: 9/3/2020 19:51:05, SnapshotRef: snapshot-3413, Type: Default'
[19.05.2020 18:42:21] <49> Info [Soap] Removing snapshot 'snapshot-3413'
[19.05.2020 18:42:21] <49> Info [VimApi] RemoveSnapshot, type "VirtualMachineSnapshot", ref "snapshot-3413", removeChildren "False"

//VPXD:
2020-05-19T15:42:17.312Z info vpxd[49540] [Originator@6876 sub=vpxLro opID=7e40daff] [VpxLRO] -- BEGIN task-32181 -- snapshot-3413 -- vim.vm.Snapshot.remove -- 528b44cf-9794-1f2d-e3ff-e3e78efc8f76(52b14d11-1813-4647-353f-cfdcfbc6c149)

//Hostd:
2020-05-19T15:42:17.535Z info hostd[2099313] [Originator@6876 sub=Vimsvc.TaskManager] Task Completed : haTask-676-vim.vm.Snapshot.remove-5370588 Status success
2020-05-19T15:42:17.302Z info hostd[6710322] [Originator@6876 sub=Vimsvc.TaskManager opID=7e40daff-e0-6513 user=vpxuser:VSPHERE.LOCAL\Administrator] Task Created : haTask-676-vim.vm.Snapshot.remove-5370588

Ищем компоненты

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

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

И да, это будет опять vSphere. Получить общую информацию проще всего в логе таски по строке Processing object

[02.11.2020 05:00:38] <29> Info Processing object 'vudc01' ('vm-26') from host 'vcenter.test.local' ('3de6c11c-ad7e-4ec0-ba12-d99a0b30b493')

Чуть ниже уже будет более подробная информация в строке VM information. Как видим, для машин, добавленных через VC, указывается, в том числе, и хост.

[01.11.2020 05:00:46] <26> Info VM information: name "vudc01", ref "vm-26", uuid "564d7c38-f4ae-5702-c3c9-6f42ef95535c", host "esx02.test.local", resourcePool "resgroup-22", connectionState "Connected", powerState "PoweredOn", template "False", changeTracking "True", configVersion "vmx-08"

Далее следует масса информации про выбор прокси и доступных режимов работы. Всё это происходит под тегом [ProxyDetector]. Общий алгоритм таков: берём и проверяем возможность скачать диски поочередно в режимах SAN > HotAdd > NBD. Каким способом получилось, так и качаем. Начинается всё веселье в этом моменте:

[01.11.2020 05:00:24] <01> Info [ProxyDetector] Trying to detect source proxy modes for VM [vudc01], has snapshots:False, disk types:[Scsi: True, Sata: False, Ide: False, Nvme: False]
[01.11.2020 05:00:24] <01> Info [ProxyDetector] Host storage 'VMware ESXi 6.5.0 build-16207673' has 1 luns

И дальше полная вакханалия проверок, так как проверяются все возможные прокси на все возможные режимы. Да ещё и два раза — как таргет и как сорс. Единственное исключение возможно только в том случае, если в настройках джобы указан конкретный прокси и запрещены все режимы кроме одного.  

[16.09.2020 00:08:01] <01> Info [ProxyDetector] Trying to detect source proxy modes for VM [TinyLinux2], has snapshots:False, disk types:[Scsi: True, Sata: False, Ide: False, Nvme: False]
[16.09.2020 00:08:11] <01> Info [ProxyDetector] Detecting storage access level for proxy [VMware Backup Proxy]
[16.09.2020 00:08:11] <01> Info Proxy [VMware Backup Proxy] - is in the same subnet as host [VMware ESXi 6.7.0 build-16
[16.09.2020 00:08:11] <01> Info [ProxyDetector] Detected mode [nbd] for proxy [VMware Backup Proxy]
...
[16.09.2020 00:08:13] <01> Info [ProxyDetector] Trying to detect target proxy modes, sanAllowed:False, vmHasSnapshots:True, diskTypes:[Scsi: True, Sata: False, Ide: False, Nvme: False], vmHasDisksWithoutUuid:False
[16.09.2020 00:08:24] <01> Info [ProxyDetector] Detecting storage access level for proxy [10.1.10.6]
[16.09.2020 00:08:24] <01> Info [ProxyDetector] Detected mode [nbd] for proxy [10.1.10.6]

Какой прокси, в каком режиме и куда был назначен — надо смотреть в логе каждой таски по фразе Preparing for processing of disk

[16.09.2020 01:03:28] <20> Info Preparing for processing of disk [shared-spbsupstg02-ds04] TinyLinux2/TinyLinux2.vmdk, resources: source proxy 'VMware Backup Proxy' and target proxy '10.1.10.6'
[16.09.2020 01:03:28] <34> Info Processing disk '[shared-spbsupstg02-ds04] TinyLinux2/TinyLinux2.vmdk'
[16.09.2020 01:03:28] <34> Info Using source proxy 'VMware Backup Proxy' and target proxy '10.1.10.6' for disk processing

Также полезное можно найти в логе /Utils/VMC.log. С ним только одна сложность: вся информация внутри представлена в виде ID. Никаких имён и человекочитаемых названий. Слава роботам!

[16.09.2020 04:05:40] <56> Info [ViProxyEnvironment] Initialization of ViProxyEnvironment for the proxy 10.1.10.6 (5c7f925e-999b-473e-9a99-9230f51d5ebb).

Если мы говорим про Direct SAN режим, то самое важное — это корректность сопоставления LUN’ов с их номерами. В данном примере виден общий смысл происходящего: сначала получаем номера лунов, проверяем все подключённые к прокси луны на предмет нахождения идентичного и в случае успеха работаем с ним.

[04.06.2019 17:54:05] <01> Info [ProxyDetector] Searching for VMFS LUN and volumes of the following datastores: ['test_datastore']
[04.06.2019 17:54:05] <01> Info [ProxyDetector] Datastore 'test_datastore' lun was found, it uses vmfs
[04.06.2019 17:54:05] <01> Info [ProxyDetector] VMFS LUNs: ['NETAPP iSCSI Disk (naa.60a980004270457730244a48594b304f)'], NAS volumes: <no>
...
[04.06.2019 17:54:16] <01> Info [ProxyDetector] Proxy [VMware Backup Proxy]: Detecting san access level
[04.06.2019 17:54:16] <01> Info [ProxyDetector] Proxy [VMware Backup Proxy]: disks ['6000C29C75E76E488EC846599CAF8D94566972747561','6000C29EA317A4903AFE2B7B038D3AD6566972747561','6000C29274D8E07AAE27F7DB20F38964566972747561','60A980004270457730244A48594B304F4C554E202020','6000C29EE0D83222ED7BFCB185D91117566972747561','6000C292083A3095167186895AD288DB566972747561','6000C2950C4F2CB5D9186595DC6B4953566972747561','6000C29BF52BB6F46A0E6996DA6C9729566972747561']
...
[04.06.2019 17:54:16] <01> Info [ProxyDetector] Proxy VMware Backup Proxy disk: , disk inquiry: 
SCSI Unique ID 60A980004270457730244A48594B304F4C554E202020 is accessible through san for ESXi with vmfs lun: NETAPP iSCSI Disk (naa.60a980004270457730244a48594b304f)

Эти же номера можно проверить самим. В vSphere клиенте — в разделе Host > Configure > Storage devices, а в Windows посмотреть в стандартный Disk Manager. Все номера должны совпадать.

Репозиторий

В отличие от бекапа, реплика хранится непосредственно на сторадже хоста. Репозиторию Veeam отводится роль хранителя метаданных. Под каждое задание создаётся своя папка, где хранятся .vbk файлы, содержащие так называемые дайджесты. Чтобы найти конкретный, открываем лог таски и ищем [DigestsRepositoryAccessor]. Получаем путь, название репозитория и ID. 

[15.09.2020 05:44:54] <19> Info [DigestsRepositoryAccessor] Creating new digests storage at [E:\Replicas\Replication_Job_4_7b409570-c4e1-424f-a0c5-b0b6e6e47272_vm-34412\2020-09-15T024444.vbk].
[15.09.2020 05:33:54] <21> Info Setting repository 'Backup Repository 1' ('adf7fbb6-0337-4805-8068-77960414f406') credentials for backup client.

Если репозиторием выступает сетевая шара, то будет написан её путь:

[15.09.2020 06:50:53] <41> Info [DigestsRepositoryAccessor] Creating new digests storage at [\\172.17.12.57\test\Replicas\Replication_Job_4_7b409570-c4e1-424f-a0c5-b0b6e6e47272_vm-34432\2020-09-15T035033.vbk]

Если углубиться в поисках, то по Setting repository можно найти не только ID и название, но и под какой учёткой мы туда ходим. Если вы используете не одну учётку для всего на свете, то запросто можно промахнуться в визарде и долго искать причину, почему не удаётся подключиться к серверу. 

[15.09.2020 06:50:02] <20> Info Setting repository 'DD share' ('36a89698-2433-4c1a-b8d3-901d9c07d03a') credentials for backup client.
[15.09.2020 06:50:02] <20> Info Creds user name: ddve\sysadmin
[15.09.2020 06:50:02] <20> Info Setting share creds to [\\172.17.12.57\test]. CredsId: [66de1ea7-7e89-48f6-bc73-61a4d1a7621e]
[15.09.2020 06:50:02] <20> Info Setting share creds to [\\172.17.12.57\test]. Domain: [ddve], User: [sysadmin]

WAN акселераторы

Получившая недавно второе рождение функция, которая бывает особенно актуальна для реплик. Проверить, работают акселераторы или нет, можно, найдя в логе джобы  флаг <UseWan>. А по строке Request: SourceWanAccelerator можно получить информацию об ID используемых акселераторах.

[15.09.2020 05:32:59] <01> Info - - Request: SourceWanAccelerator: [WanAccelerator '8f0767e1-99ab-4050-a414-40edc5bebc39'], TargetWanAccelerator: [WanAccelerator '22fa299c-8855-4cf8-a6c7-6e8587250750']
[15.09.2020 05:32:59] <01> Info - - - - Response: Subresponses: [Wan accelerator],[Wan accelerator]

В таск логе имена будут указаны уже в явном виде

[15.09.2020 05:33:54] <21> Info Using source WAN Accelerator KK-BB2
[15.09.2020 05:33:54] <21> Info Using target WAN Accelerator 10.1.10.6

Что за второе рождение упоминалось в начале? Это так называемый High Bandwidth режим. Если раньше смысл от акселераторов был только на действительно медленных линках (очень медленных линках), то в v10 был введён новый режим, обеспечивающий прирост в производительности на скоростях до 100 Мб/с. Включается он отдельной галочкой, а в логах таски это видно вот по этим строкам:

 [15.09.2020 05:33:54] <21> Info Selecting WaTransport algorithm, input arguments: performance mode preferred: False, perf mode available on target WAN: False
[15.09.2020 05:33:54] <21> Info Selecting WaTransport algorithm: selected classic mode

В первой строке указаны результаты проверки, включён ли необходимый режим на обоих WA — мы видим, что нет, и выбираем классическую версию. 

Просто полезные слова для поиска

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

Backup/Replication Job log

"> Error" или "> Warning" — здесь что-то произошло, на что точно надо обратить внимание. Не обязательно всё сломалось именно тут, но что-то здесь точно произошло. Возможно даже пошло не так, как планировалось.

Job Options: — здоровенная XML, где перечислены все настройки задания. После неё обычно идёт раздел VSS Settings, где перечислены настройки VSS.

[RetentionAlgorithm] — момент отрабатывания ретеншн алгоритма. Тут удаляются ставшие ненужными точки или синтезируются новые.

[JobSession] Load: — ботлнеки, про которые в нашем блоге есть отдельная статья.

Preparing point — узнаём, в каком режиме создаётся бекап (инкремент, реверс инкремент или фул).

Starting agent — узнаём, какой агент когда был запущен, и по его ID идём читать соответствующий ему лог.

VMware Job

[ProxyDetector] — весь процесс выбора рабочих прокси и режима транспорта. Технически, в Hyper-V будет всё то же самое, только с гораздо меньшим количеством деталей.

[SanSnapshots] — блок создания и работы с SAN-снапшотами.

VM task — детальная информация о каждой конкретной машине в задании.

Hyper-V Job

VM tasks — в отличие от VMware тут не будет исчерпывающей информации, однако как отправная точка для поиска истины — самое то.

VM guest info — много информации о гостевой машине и самом хосте. Однако имя машины надо предварительно посмотреть в секции Creating task, которая немного выше.

Task log

Starting Disk — можно узнать, когда началась обработка конкретного диска. Очень полезно, если у машины их много, включён parallel processing и всё несколько запутано.

Operation was canceled by user — где-то рядом ещё должно быть “Stop signal has been received”. Указывает на реальное время остановки бекапа и может означать всё что угодно. Если время подозрительно красивое, вроде 06:00:00, а юзер мамой клянётся, что ничего не трогал, то 99,99% — установлено Backup Window и ваше время истекло. 

Starting agent — опять же, получаем ID нужного агента и далее смотрим прицельно.

Preparing oib — указывает, готовится ли бекап машины в инкрементальном виде или фул.

.source. shows — показывает, на каком сервере будет запущен передающий агент (Source Proxy).

.target. — показывает, на каком сервере будет запущен принимающий агент (Repository/Target proxy).

VMware Task

VM information: Практически вся информация, которую можно узнать про целевую машину.

[VimApi] Create или [VimApi] Remove — создание и удаление снапшотов. Через [VimApi] делается ещё несколько действий, так что не удивляйтесь.

Hyper-V Task

Files to process — краткий список того, что будет забекаплено.

[RTS] — весь процесс создания снапшотов и их удаления.

Agent log

Err | или WARN| — то же самое, что и > Error > Warning. В Err действительно есть пробел перед палочкой, это не опечатка.

Traffic size — размер всей переданной информации.

stat – размер файла бекапа.

Backup service log

==  Name — показывает абсолютно все джобы и их текущее состояние (работает или остановлена). Между == и названием два пробела.

[Scheduler] Ready to start jobs: — список джоб, которые будут запущены в соответствии с расписанием.

by user — эта пометка делается, если юзер что-то сделал сам.

Backup copy job log

[OibFinder] — покажет вам, какие репозитории и точки восстановления были исключены из обработки. Иногда даже может сказать, почему.

[CryptoKeyRecryptor] — позволит понять, менялся ли на этом проходе юзер-пароль или энтерпрайз-ключ.

Surebackup

Backup point или Replica point — время, когда была создана проверяемая точка.

[<vm name>] [PowerOnVm] [StableIp] — моменты включения и выключения машин в лаборатории.

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

Поэтому, если есть вопросы, то добро пожаловать в комментарии. Если есть предложение по написанию подобной статьи на какую-то конкретную тему — адрес тот же, комментарии.

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