Как читать логи ошибок

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

Что такое логи

Это текстовые файлы, которые хранятся на жестком диске сервера. Создаются и заполняются в автоматическом режиме, в хронологическом порядке. В них записываются:

• системная информация о переданных пользователю данных;
• сообщения о сбоях и ошибках;
• протоколирующие данные о посетителях платформы.

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

Классификация логов

Для каждой разновидности софта предусмотрены соответствующие файлы. Все логи сервера могут храниться на одном диске или даже на отдельном сервере. Существует довольно много разновидностей логов, вот наиболее распространенные:

• доступа (access_log) — записывают IP-адрес, время запроса, другую информацию о пользователях;
• ошибок (error_log) — показывают файлы, в которых выявлены ошибки и классифицируют сбои;
• FTP-авторизаций — отображают данные о попытках входа по FTP-соединению;
• загрузки системы — с его помощью выполняется отладка при появлении проблем, в файл записываются основные системные события, включая сбои;
• основной — содержит информацию о действиях с файерволом, DNS-сервером, ядром системы, FTP-сервисом;
• планировщика задач — в нем выполняется протоколирование задач, отображаются ошибки при запуске cron;
• баз данных — хранит подробности о запросах, сбоях, ошибки в логах сервера отображаются наравне с другой важной информацией;
• хостинговой панели — включает статистику использования ресурсов сервера, время и количество входов в панель, обновление лицензии;
• веб-сервера — содержит информацию о возникавших ошибках, обращениях;
• почтового сервера — в нем ведутся записи о входящих и исходящих сообщениях, отклонениях писем.

Записи в системные журналы выполняет установленный софт.

Зачем нужны логи

Анализ логов сервера — неотъемлемая часть работы системного администратора или веб-разработчика. Обрабатывая их, специалисты получают массу полезных сведений. Используются в следующих целях:

• поиск ошибок и сбоев в работе системы;
• выявление вредоносной активности;
• сбор статистики посещения веб-ресурса.

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

Где посмотреть логи

Расположение определяется хостинг-провайдером или настройками установленного софта. На виртуальном хостинге доступ к лог-файлам предоставляется из панели управления хостингом. Если администратор не открыл его для владельца сайта, получить информацию не получится. Но большинство провайдеров разрешают свободно пользоваться журналами и проводить анализ логов сервера. Независимо от разновидности сервера лог-файлы хранятся в текстовом документе. По умолчанию он называется access.log, но настройки позволяют переименовать файл. Это актуально для Nginx, Apache, прокси-разновидностей squid, других типов. Для просмотра их надо скачать и открыть в текстовом редакторе. В качестве альтернативы можно использовать Grep и схожие утилиты. Они позволяют открыть и отфильтровать логи прямо на сервере.

Как читать логи. Пример

Существует довольно много форматов записи, combined — один из наиболее распространенных. В нем строчка кода может выглядеть так:

%h %l %u %t «%r» %>s %b «%{Referer}i» «%{User-Agent}i»

Директивы имеют следующее значение:

• %h — IP-адрес, с которого был сделан запрос;
• %l — длинное имя удаленного хоста;
• %u — удаленный пользователь, если запрос был сделан аутентифицированным юзером;
• %t — время запроса к серверу и его часовой пояс;
• %r — тип и содержимое запроса;
• %s — код состояния HTTP;
• %b — количество байт информации, отданных сервером;
• %{Referer} — URL-источник запроса;
• %{User-Agent} — HTTP-заголовок.

Еще один пример чтения логов можно посмотреть в статье «Как читать логи сервера».

Опытные веб-мастера для сбора и чтения лог-файлов используют программы-анализаторы. Они позволяют читать логи сервера без значительных временных затрат. Вот некоторые из наиболее востребованных:

• Analog. Один из самых популярных анализаторов, что во многом объясняется высокой скоростью обработки данных и экономным расходованием системных ресурсов. Хорошо справляется с объемными записями, совместим с любыми ОС.
• Weblog Expert. Программа доступна в трех вариациях: Lite (бесплатная версия), Professional и Standard (платные релизы). Версии отличаются функциональными возможностями, но каждая позволяет анализировать лог-файлы и создает отчеты в PDF и HTML.
• SpyLOG Flexolyzer. Простой аналитический инструмент, позволяющий получать отчеты с высокой степенью детализации. Интегрируется c системой статистики SpyLOG, позволяет решать задачи любой сложности.

Логи сервера с ошибками error.log

Это журнал с информацией об ошибках на сайте. В нем можно посмотреть, какие страницы отсутствуют, откуда пришел пользователь с конкретным запросом, имеются ли «битые» ссылки, другие недочеты, включая те, которые не удалось классифицировать. Используется для выявления багов и погрешностей в коде.

Каждая ошибка в логе сервера error.log отображается с новой строки. Идентифицировав и устранив ее, программист сможет наладить работу сайта. Используя журнал, можно выявить и слабые места веб-платформы. Это простой и удобный инструмент анализа, которым должен уметь пользоваться каждый веб-мастер, системный администратор и программист.

Скажите честно, в своей практике вам чаще приходилось сталкиваться с логами, напоминающими чей-то поток сознания, или всё же это были красивые структурированные файлы, на которые любо-дорого смотреть? Надеюсь, что второе. В наших продуктах, само собой, мы тоже стремимся идти по второму пути, однако необходимость зафиксировать большое количество процессов накладывает свой отпечаток. Так что сегодня мы научимся не “читать книгу и видеть фигу”, а бесстрашно открывать любой лог 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-VVHDsSRV-DCFS02SRV-DCFS02-C.vhdx].

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

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

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

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

===================================================================
Starting new log
Log has been started by 'VEEAMSYSTEM' 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 FilesVeeamBackup and ReplicationBackupVeeam.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 'VEEAMSYSTEM' user (Non-interactive)
MachineName: [VEEAM], OS: [Microsoft Windows Server 2019 Standard (10.0.17763)],

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

Module: [C:Program FilesVeeamBackup and ReplicationBackupVeeam.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.LOCALAdministrator] 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.LOCALAdministrator] 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.LOCALAdministrator] 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.LOCALAdministrator] 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.LOCALAdministrator] 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.LOCALAdministrator] 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.LOCALAdministrator] 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:ReplicasReplication_Job_4_7b409570-c4e1-424f-a0c5-b0b6e6e47272_vm-344122020-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.57testReplicasReplication_Job_4_7b409570-c4e1-424f-a0c5-b0b6e6e47272_vm-344322020-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: ddvesysadmin
[15.09.2020 06:50:02] <20> Info Setting share creds to [\172.17.12.57test]. CredsId: [66de1ea7-7e89-48f6-bc73-61a4d1a7621e]
[15.09.2020 06:50:02] <20> Info Setting share creds to [\172.17.12.57test]. 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 примерно три месяца, так что охватить всю широту наших глубин в рамках серии статей задача утопическая. Да и новая версия не за горами и часть информации может стать более невалидной.

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

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

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

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

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

Для чего нужны логи

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

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

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

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

Маркетинг. Логи — источник ценной информации для развития сайта. Они позволяют собрать статистику по посещаемости с «сырыми» техническими данными. Например, понять, откуда приходят пользователи, где они находятся и какими устройствами пользуются для визита.

Какими бывают логи

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

• основной рассказывает о главных событиях, которые произошли непосредственно с серверным ПО;
• журнал доступа содержит сведения о посетителях сайта;
• лог ошибок сообщает обо всех сбоях, которые произошли во время работы ПО;
• лог веб-сервера рассказывает об обращениях к серверу и о возможных ошибках;
• лог баз данных записывает сведения о действиях с БД, запросах и ошибках;
• лог почтового сервера содержит информацию об отправленных и полученных письмах и так далее.

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

Что может содержаться в логах

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

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

Как правильно читать лог

Вручную. Логи хранятся в файлах с расширением .log. Их можно открыть как обычные текстовые файлы и просмотреть содержимое. Перед этим стоит посмотреть, как настроен формат записи логов, если у вас есть доступ к этим параметрам.

Например, так выглядит формат по умолчанию для лога доступа с веб-сервера:

[доменное имя сайта][IP-адрес пользователя][дата и время визита][тип запроса][URL, к которому обратился пользователь][протокол, по которому пользователь соединился с сайтом][код ответа сервера][количество байт информации, которую передали пользователю][дополнительная информация]

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

Это не единственный возможный способ записи лога. Например, в логе ошибок каждая строчка — это запись об ошибке с полной информацией о ней: датой и временем, адресом страницы, на которой возник сбой, и так далее.

С помощью анализатора. Второй вариант — не просматривать лог вручную, а воспользоваться специальной программой-анализатором. Она парсит лог-файл — «разбирает» его на составляющие и представляет в удобном для пользователя виде. Так информация показывается в виде понятного отчета, иногда с графиками и диаграммами.

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

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

Узнать больше о сетевых технологиях и получить новую профессию вы можете на курсах. Записывайтесь и станьте востребованным IT-специалистом.

Содержание:

• Важные логи сайта
• Расположение логов
• Чтение записей в логах
• Просмотр с помощью команды tail
• Просмотр с помощью ISPManager
• Программы для анализа логов
• Ведение логов медленных запросов сервера
• Ведение логов с помощью Logrotate

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

Важные логи сайта

• Access.log — логи посещений пользователей и ботов. Позволяет составить более точную и подробную статистику, нежели сторонние ресурсы, выполняющие внешнее сканирование сайта и отправляющие ряд ненужных запросов серверу. Благодаря данному логу можно получить информацию об используемом браузере и IP-адрес посетителя, данные о местонахождении клиента (страна и город) и многое другое. Стоит обратить внимание, если сайт имеет высокую посещаемость, то анализ логов сервера потребует больше времени. Поэтому для составления статистики стоит использовать специализированные программы (анализаторы).
• Error.log — программные ошибки сервера. Стоит внимательно отнестись к анализу данного лога, ведь боты поисковиков, сканируя, получают все данные о работе сайта. При обнаружении большого количества ошибок, сайт может попасть под санкции поисковых систем. В свою очередь из записей данного журнала можно узнать точную дату и время ошибки, IP-адрес получателя, тип и описание ошибки.
• Slow.log (название зависит от используемой оболочки сервера) — в данный журнал записываются медленные запросы сервера. Так принято обозначать запросы с повышенным порогом задержки, выданные пользователю. Этот журнал позволяет выявить слабые места сервера и исправить проблему. Ниже будет рассмотрен способ включить ведение данного лога на разных типах серверов, а также настройка задержки, с которой записи будут заноситься в файл.

Расположение логов

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

Стандартные пути до Error.log

Nginx

/var/log/nginx/error.log

Php-Fpm

/var/log/php-fpm/error.log

Apache (CentOS)

/var/log/httpd/error_log

Apache (Ubuntu, Debian)

/var/log/apache2/error_log

Стандартные пути до Access.log

Nginx

/var/log/nginx/access.log

Php-Fpm

/var/log/php-fpm/access.log

Apache (CentOS)

/var/log/httpd/access_log

Apache (Ubuntu, Debian)

/var/log/apache2/access_log

Чтение записей в логах

Записи в логах имеют структуру: одно событие – одна строка.

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

Примеры записей

Error.log

[Sat Sep 1 15:33:40.719615 2019] [:error] [pid 10706] [client 66.249.66.61:60699] PHP Notice: Undefined variable: moduleclass_sfx in /var/data/www/site.ru/modules/contacts/default.php on line 14

В приведенном примере:

• [Sat Sep 1 15:33:40.719615 2019] — дата и время события.
• [:error] [pid 10706] — ошибка и её тип.
• [client 66.249.66.61:60699] — IP-адрес подключившегося клиента.
• PHP Notice: Undefined variable: moduleclass_sfx in — событие PHP Notice. В данной ситуации — обнаружена неизвестная переменная.
• /var/data/www/site.ru/modules/contacts/default.php on line 14 — путь и номер строки в проблемном файле.

Access.log

194.61.0.6 – alex [10/Oct/2019:15:32:22 -0700] "GET /apache_pb.gif HTTP/1.0" 200 5396 "http://www.mysite/myserver.html" "Mozilla/4.08 [en] (Win98; I ;Nav)"

В приведенном примере:

• 194.61.0.6 — IP-адрес пользователя.
• alex — если пользователь зарегистрирован в системе, то в логах будет указан идентификатор.
• [10/Oct/2019:15:32:22 -0700]— дата и время записи.
• «GET /apache_pb.gif HTTP/1.0» — «GET» означает, что определённый документ со страницы сайта был отправлен пользователю. Существует команда «POST», наоборот отправляет конкретные данные (комментарий или любое другое сообщение) на сервер . Далее указан извлечённый документ «Apache_pb.gif», а также использованный протокол «HTTP/1.0».
• 200 5396 — код и количество байтов документа, которые были возвращены сервером.
• «http://www. www.mysite/myserver.html»— страница, с которой был произведён запрос на извлечение документа «Apache_pb.gif».
• «Mozilla/4.08 [en] (Win98; I ;Nav)» — данные о пользователе, которой произвёл запрос (используемый браузер и операционная система).

Просмотр логов сервера с помощью команды tail

Выполнить просмотр логов в Linux можно с помощью команды tail. Данный инструмент позволяет смотреть записи в логах, выводя последние строки из файла. По умолчанию tail выводит 10 строк.

Первый вариант использования Tail

tail -f /var/log/syslog

Аргумент «-f» позволяет команде делать просмотр событий в режиме реального времени, в ожидании новых записей в лог файлах. Для прерывания процесса следует нажать сочетание клавиш «Ctrl+C».

На место переменной «/var/log/syslog» в примере следует подставить актуальный адрес до нужных системных журналов.

Второй вариант использования Tail

tail -F /var/log/syslog

В Linux логи веб-сервера не ведутся до бесконечности, поскольку это усложняет их дальнейший анализ. При преодолении лимита записей, система переименует переполненный строками файл журнала и отправит в «архив». Вместо старого файла создастся новый, но с прежним названием.

Если будет использоваться аргумент «-f», команда продолжит отслеживание старого, переименованного журнала. Данный метод делает невозможным просмотр логов в реальном времени, поскольку файл более не актуален.

При использовании аргумента «-F», команда, после окончания записи старого журнала, перейдёт к чтению нового файла с логами. В таком случае просмотр логов в режиме реального времени продолжится.

Аналог команды Tail

tailf /var/log/syslog

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

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

Изменение стандартного количества строк для вывода

Как и отмечалось выше, по умолчанию выводится 10 строк. Если требуется увеличить или уменьшить их количество, в команду добавляется аргумент «-n» и необходимое число строк.

Пример:

tail -f -n 100 /var/log/syslog

При использовании данной команды будут показаны последние 100 строк журнала.

Просмотр логов с помощью ISPManager

Если на сервере установлен ISPManager, логи можно легко читать, используя приведенный ниже алгоритм.

1. На главной странице, в панели инструментов «WWW» нужно нажать на вкладку «Журналы».
   
2. ISPManager выдаст журналы посещений и серверных ошибок в виде:
   • ru.access.log;
   • ru.error.log.*

   * Вместо «newdomen.ru» из примера в выдаче будет название актуального домена.

   Открыть файл лога можно, нажав на «Посмотреть» в верхнем меню.

3. Для просмотра всех записей журнала, необходимо нажать на «Скачать» и сохранить файл на локальный носитель.
   
4. Более старые версии логов можно найти во вкладке «Архив».
   

Программы для анализа логов

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

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

Статические программы

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

WebLog Expert

Возможности

• Предоставление информации об активность сайта, количестве посетителей, доступ к файлам, URL страницы, ссылающиеся страницы, информацию о пользователе (браузер и операционная система).
• Создание отчётов в формате HTML (.html), PDF (.pdf), CSV (.csv).
• Поддерживает анализ логов Nginx, Apache, ISS.
• Чтение файлов даже в архивах ZIP (.zip), GZ (.gz).

Web Log Explorer

Возможности

• Создание многоуровневых отчётов, включающих количество посетителей, маршруты пользователей по сайту, местоположение хостов (страна и город), указанные в поисковике ключевые слова.
• Поддержка более 43 форматов логов.
• Возможность прямой загрузки логов с FTP, HTTP сервера.
• Чтение архивированных журналов.

Программы для анализа в режиме реального времени

Эти инструменты встраиваются в программную среду сервера, анализируют данные в реальном времени и записывают непрерывный отчёт.

GoAccess

Возможности

• Автоматическая генерация отчёта в формате HTML (.html), JSON (.json), CSV (.csv).
• При подключении к серверу через SSH, возможен анализ в браузере и в терминале
• Поддержка почти всех форматов (Apache, Nginx, Amazon S3, Elastic Load Balancing, CloudFront и др.).

Logstash

Возможности

• Постоянная генерация отчёта в файл JSON (.json).
• Получение и анализ информации из нескольких источников.
• Возможность пересылать журналы с помощью Filebeat.
• Поддержка анализа системных журналов.
• Поддерживается большое количество форматов: от Apache до Log4j (Java).

Ведения логов медленных запросов сервера

Анализ данного лога позволяет определить на какие типы запросов сервер отвечает долго. В идеале задержка должна составлять не более 1 секунды.

На некоторых типах оболочек (MySQL, PHP-FPM) ведение данного лога по умолчанию отключено. Процесс запуска и ведения зависит от сервера.

MySQL

Если сервер управляется с помощью MySQL, то необходимо создать каталог и сам файл для ведения журнала с помощью команд:

mkdir /var/log/mysql

touch /var/log/mysql/mysql-slow.log

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

chown mysql:mysql /var/log/mysql/mysql-slow.log

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

mysql -uroot -p

Для запуска и настройки ведения логов нужно последовательно ввести в терминале следующие команды:

> SET GLOBAL slow_query_log = 'ON';

> SET GLOBAL slow_launch_time = 2;

> SET GLOBAL slow_query_log_file = '/var/log/mysql/mysql-slow.log';

> FLUSH LOGS;

В примере:

• slow_query_log — запускает ведение журналов медленных запросов.
• slow_launch_time — указывает максимальную задержку отклика, после которой статистика запроса попадёт в журнал. В данном случае запись в логи происходит при преодолении откликом порога 2 секунды.
• slow_query_log_file — задаёт путь до используемого журнала.

Проверить статус и параметры ведения лога медленных запросов можно командой:

> SHOW VARIABLES LIKE '%slow%';

Выход из консоли MySQL выполняется командой:

> exit

После выполнения всех предыдущих действий, можно просмотреть логи сервера. Для этого в терминале вводится:

tail -f /var/log/mysql/mysql-slow.log

PHP-FPM

Для ведения журнала на данной оболочке, необходимо отредактировать параметры в конфигурационном файле. Для этого в терминале вводится команда:

vi /etc/php-fpm.d/www.conf

Далее нужно найти строки:

• request_slowlog_timeout = 10s — параметр, позволяющий указать задержку, с которой запись о длительном запросе попадёт в журнал.
• slowlog = /var/log/php-fpm/www-slow.log — параметр, указывающий путь до актуального файла логирования (.log).

После применения изменений, необходимо перезагрузить сервер PHP-FPM. Для этого в консоль вводится команда:

systemctl restart php-fpm

Просмотр логов запускается командой:

tail -f /var/log/php-fpm/www-slow.log

Анализ логов медленных запросов

Логи медленных запросов могут за незначительное время вырасти до огромных размеров. Для сортировки и отображения повторяющихся запросов рекомендуется использовать программу MySQLDumpSlow.

Для запуска просмотра логов с помощью этой утилиты, нужно составить команду по приведенному ниже алгоритму:

mysqldumpslow местонахождение/файла

Ведение логов в Logrotate

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

Изначально программа отсутствует в системе. Ниже приведены команды для инсталляции Logrotate из официальных репозиториев.

Ubuntu, Debian:

sudo apt install logrotate

CentOS:

sudo yum install logrotate

После установки необходимо проверить путь для будущих конфигурационных файлов. Для правильной работы они должны находится в папке «logrotate.d». Проверить данный параметр можно открыв конфигурационный файл  командой:

nano /etc/logrotate.conf

В директории «RPM packages drop log rotation information into this directory» должна присутствовать строка:

include /etc/logrotate.d

Теперь создаётся конфигурационный файл «rsyslog.conf». В нём будет находиться конфигурацию по работе с логами. Для создания файла в терминале вводится команда:

sudo nano /etc/logrotate.d/rsyslog.conf

В окне терминала откроется текстовой редактор. Теперь нужно внести конфигурацию, как указано в образце. В качестве примера будет использоваться журнал посещений «Access.log» (Nginx).

/var/log/nginx/access.log {
daily
rotate 3
size 500M
compress
delaycompress
}

Теперь остаётся только запустить Logrotate. Для этого вводится команда:

sudo logrotate -d /etc/logrotate.d/rsyslog.conf

Для проверки правильности работы программы в терминале можно ввести команду:

ls /var/cron.daily/