Как понимать логи ошибок

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

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

Есть несколько видов логов:

  1. Логи доступа.
    Показывают, какой пользователь, в какую дату и время, по какой ссылке перешел
    на ресурс и каков был получен ответ. Данные записи помогают найти уязвимое
    место, если ресурс взломают.
  2. Логи
    ошибок.     Показывают ошибки, выдаваемые при функционировании сайта либо в
    процессе обращения к его некоторым функциям. Здесь есть возможность отыскать и ликвидировать
    баг, приводящий к ошибке.
  3. Другие
    логи.     Фиксируют события в различных серверских компонентах: логи почты
    сервера и т.п.

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

В таком случае системные администраторы или seo специалисты начинают анализировать посетителей, идентифицировать доступ к файлам со стороны постороннего лица, а именно IP-адрес, откуда он был осуществлен, после чего делают соответствующие выводы.

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

Как включить журнал записей?

В большинстве случаев хостер отключает функцию записи логов на хостинге, чтобы сохранить больше места на диске. На примере админки хостинга Beget.com рассмотрим, как активировать запись логов:

  1. Заходим в панель администратора и находим вкладку Журналы — логи доступа.
  2. В соответствующем поле выбираем домен ресурса и кликаем на ползунки Журнал доступа, Журнал ошибок, чтобы он перешел в положение ВКЛ.

Включение логов на примере хостинга Beget

Здесь же вы видите путь, где располагаются ваши логи

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

Как посмотреть логи сервера?

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

Логи хранятся в файле access.log в системной папке любого сервера, будь то Nginx, Apache или любой другой. Лог-файлы открываются через текстовые редакторы. Любая строчка здесь соответствует не больше, чем одному обращению.

Отыскать логи можно и через панель управления хостинга, а именно в разделах Логи или Журналы.

Анализ логов сервера

Рассмотрим строку, взятую с записи одного из логов сервера: 

site.ru 85.91.97.104 - - [11/Feb/2019:05:31:09 +0200] "GET /page/3/ HTTP/1.0" 200 70214 "-" "Ahrefs Bot (http://www.ahrefs.com/bot; bot@ahrefs.com)"

И рассмотрим значение всех символов, которые здесь есть:

  • site.ru – адрес рассматриваемого ресурса
  • 85.91.97.104 – IP-адрес пользователя, посетившего сайт, после которого идет дата и время перехода на страницу и часовой пояс
  • GET – запрос, означающий получение данных. Может быть еще запрос POST, то есть, отправка данных, к примеру, авторизация на сайте
  • page/3 – обращение сделано к 3-й странице
  • HTTP/1.0 – протокол пользователя, посредством которого он зашел на ресурс
  • 200 – код ответа, отправленного сервером посетителю
  • 70214 – число байт, переданных пользователю
  • Ahrefs Bot (http://www.ahrefs.com/bot; bot@ahrefs.com) – данные о пользователе или боте, с какого устройства он зашел, какую ОС использует и т.п. В нашем случае это бот парсера ahrefs.

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

  • WebAlyzer;
  • Webtrends;
  • Awstats.

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

На некоторых хостингах их можно установить при включении логов. Например в ранее нами рассматриваемом хостинге Beget.com когда мы включаем логи, нам предлагается установить Awstats.

Установка AWStats

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

Лог ошибок error.log

Это файл, где тоже протоколируются логи, но они относятся не
к пользователям, а к ошибкам, возникающим на сервере. Аналогично файлу access.log, в error.log каждая
отдельная строка показывает запись только одной ошибки. Благодаря этому файлу
можно узнать причину возникновения ошибки и ее тип, а также IP пользователя, которому она была
показана. Рассмотрим пример:

[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
  • Первая строка: дата и время/тип записи error (ошибка), а также IP адрес пользователя.
  • Вторая: событие PHP Notice – уведомление, расшифровка Undefined variable – неизвестная переменная.
  • Третья: путь к файлу с уведомлением и строка.

Здесь мы наблюдаем ошибку в модуле контактов, в файле default.php в строке 14.

Заключение

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

Источник

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

Как читать логи с ошибками сервера

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

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

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

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

Комьюнити теперь в Телеграм

Подпишитесь и будьте в курсе последних IT-новостей

Подписаться

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

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

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

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

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

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

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

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

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

Читайте также

Настройка Iptables для чайников

Как установить и настроить NTP на сервере

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

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

VDS Timeweb арендовать

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

Существует довольно много форматов записи, 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 [2.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 [2.17.12.57test]. CredsId: [66de1ea7-7e89-48f6-bc73-61a4d1a7621e]
[15.09.2020 06:50:02] <20> Info Setting share creds to [2.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 примерно три месяца, так что охватить всю широту наших глубин в рамках серии статей задача утопическая. Да и новая версия не за горами и часть информации может стать более невалидной.

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

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

В работе системного администратора, нередко возникает необходимость посмотреть логи сервера (Server Logs), с какими задачами работал сервер в конкретное время, какие действия совершали пользователи. Причины возникновения этой необходимости могут быть разные:

  • Сбой в работе сервера;
  • Выявление неблагонамеренных действий;
  • Анализ рабочих процессов.

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

  • 1 Что такое логи сервера?
  • 2 Как правильно читать логи сервера?
  • 3 Логи серверов на Windows
  • 4 Логи SQL сервера
  • 5 Как включить или выключить запись логов сервера?
  • 6 Где находятся логи сервера?
  • 7 Пример работы с логами сервера
  • 8 Вывод

Что такое логи сервера?

Собственно говоря, само слово «логи сервера», является банальной транслитерацией, от словосочетания «server log», которое переводится как «журнал сервера».

Существуют следующие типы логов:

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

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

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

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

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

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

Итак, запись лога доступа, из файла access.log:

mysite.biz 25.34.94.132 — — [21/Nov/2017:03:21:08 +0200] «GET /blog/2/ HTTP/1.0» 200 18432 «-» «Unknow Bot (http://www.unknow.com/bot; [email protected])»

Что она обозначает:

  • mysite.biz – домен сайта, которым вы интересуетесь;
  • 34.94.132 – IP-адрес, который использовал пользователь при заходе на сайт;
  • [21/Nov/2017:03:21:08 +0200] – дата, точное время и часовой пояс пользователя;
  • GET – запрос, который отправляется для получения данных. В том случае, если пользователь передает данные, запрос будет «POST»;
  • /blog/2/ — относительный адрес страницы, к которой был обращен запрос;
  • HTTP/1.0 – используемый протокол;
  • 200 – код ответа на запрос;
  • 18432 – количество данных, переданных по запросу, в байтах;
  • Unknow Bot (http://www.unknow.com/bot; [email protected]) – данные о роботе, или реальном человеке, который зашел на сайт. В том случае, если это человек, будет отображена ОС, тип устройства и т.д. В конкретном примере на сайт зашел робот-парсер, принадлежащий ресурсу unknow.com.

Таким образом, мы узнали, что с IP-адреса 25.34.94.132, двадцать первого ноября, 2017-го года, в три часа, двадцать одну минуту и восемь секунд, на наш сайт заходил бот, принадлежащий другому веб-ресурсу. Он отправил запрос на получение данных, и получил 18432 байт информации.

Теперь можно заблокировать доступ для ботов от этого сайта, либо от всех, кто пользуется этим IP, разумеется, если в этом есть необходимость.

Логи ошибок, можно посмотреть в файле с говорящим именем – error.log. Они выглядят следующим образом:

[Sat Oct 1 18:23:28.719615 2019] [:error] [pid 10706] [client 44.248.44.22:35877]

PHP Notice: Undefined variable: moduleclass_sfx in

/var/data/www/mysite.biz/modules/contacts/default.php on line 13

Что здесь написано?

  1. Дата, время и тип ошибки, а также IP-адрес, который использовал посетитель;
  2. Тип события, в данном случае – «PHP Notice» (уведомление), а также уточнение, что в данном случае, мы имеем дело с неизвестной переменной;
  3. Местоположение файла с уведомлением, а также строка, на которой оно находится.

Если говорить просто, то в данном случае мы имеем сообщение о том, что первого октября, в 18:23, 2019-го года, произошла ошибка, связанная с модулем контактов.

Разумеется, даже после расшифровки, полученные данные не так просто проанализировать. Именно поэтому, для удобной обработки данных из логов сервера, используется различное программное обеспечение. К таким программам относятся: Awstats, Webtrends, WebAlyzer, и многие другие.

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

Логи серверов на Windows

У логов серверов на Windows, изначально более удобный и структурированный вывод информации, в виде простой и понятной таблицы.

Существует несколько уровней событий:

  • Подробности;
  • Сведения;
  • Предупреждение;
  • Ошибка;
  • Критический.

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

Логи SQL сервера

На сегодняшний день, базы данных SQL, являются наиболее распространенным способом работы с большими объемами информации. В первую очередь, логи sql сервера, стоит изучить, если вы не уверены в том, что какие-то процессы были успешно завершены. Этими процессами могут быть:

  • Резервное копирование;
  • Восстановление данных;
  • Массовые изменения;
  • Различные скрипты, и программы для обработки данных.

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

  • Сбор данных;
  • Database Mail;
  • SQL Сервер;
  • События Windows;
  • Журнал заданий;
  • Коллекция аудита;
  • SQL Сервер, агент.

Для того, чтобы получить доступ к журналам, необходимо иметь права «securityadmin».

Как включить или выключить запись логов сервера?

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

Где находятся логи сервера?

Расположение журналов, зависит в первую очередь от используемой вами операционной системы.

Логи серверов с CentOS, или Fedora, хранятся в дирректории «/var/log/».

Названия файлов:

  • Журнал ошибок – «error.log»;
  • Журнал nginx – «nginx»;
  • Журнал доступов – «log»;
  • Основной журнал – «syslog»;
  • Журнал загрузки системы – «dmesg».

Логи ошибок, связанных с работой MySQL, находятся в директории «/var/lib/mysql/», в файле «$hostname.err».

Для операционных систем Debian и Ubuntu, логи сервера располагаются в папке «/var/log/», в файлах:

  • Nginx — журнал nginx;
  • /mysql/error.log – журнал ошибок для баз данных MySQL;
  • Syslog – основной журнал;
  • Dmesg – загрузка системы, драйвера;
  • Apache2 – журнал веб-сервера Apache.

Как видите, у всех ОС, основанных на Linux, логи сервера, как правило имеют одинаковые названия, и директории.

С логами для Windows server, дело обстоит несколько иначе. Если нужно просмотреть журналы, необходимо войти в систему, нажать клавиши «Win» и «R», после чего откроется окно просмотра событий, где есть возможность подобрать интересующие нас логи.

Если вы хотите посмотреть логи PowerShell, то необходимо открыть программу и ввести команду: «Get-EventLog -Logname ‘System’».

Все данные будут выведены в виде удобной таблицы.

Пример работы с логами сервера

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

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

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

Вывод

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

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

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

У систем, основанных на Linux, как правило примерно одинаковое расположение файлов с логами, что существенно упрощает работу с ними.

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

Загрузка…

Просмотр и анализ логов сайта на Linux сервере

Содержание:

  • Важные логи сайта
  • Расположение логов
  • Чтение записей в логах
  • Просмотр с помощью команды 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» нужно нажать на вкладку «Журналы».
    Просмотр логов с помощью ISPManager
  2. ISPManager выдаст журналы посещений и серверных ошибок в виде:
    • ru.access.log;
    • ru.error.log.*

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

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

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

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

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

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

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

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

WebLog ExpertWebLog Expert

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

Web Log Explorer

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

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

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

GoAccess

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

Logstash

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/

Источник

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

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

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

Источник

 Как читать логи сервера и что это такое?

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

Содержание:

  1. Что такое логи и зачем они нужны?
  2. Типы логов и где их найти
  3. Какая информация хранится в логах и как ее интерпретировать

Что такое логи и зачем они нужны

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

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

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

Типы логов и где их найти

Месторасположение логов зависит от используемого ПО, настроек, прописанного админом пути. Чаще всего server logs сохраняются в var/log/. Однако, не все сервисы помещают файлы регистрации в эту директорию. В любом случае, можно уточнить такую информацию у веб-хостера.
У дистрибутивов Linux CentOS или Fedora логи серверной машины лежат в /var/log/. Там можно найти:

  • файл регистрации ошибок error.log;
  • данные о доступах log;
  • основной системный журнал syslog;
  • файл загрузки ОС dmesg;
  • журнал nginx.

Лог ошибок MySQL ($hostname.err) хранится в /var/lib/mysql/. Для Debian или Ubuntu местоположение логов аналогично, за исключением log file ошибок MySQL: /mysql/error.log. А также – логи веб сервера Apache сохраняются по пути /var/log/apache2.
У ОС Windows дружной метод структурирования log-файлов. События делятся на несколько уровней:

  • предупреждение – Warning;
  • подробности (System и EventData);
  • ошибка – Error;
  • сведения – Information;
  • критический – Critical.

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

Какая информация хранится в логах и как ее интерпретировать?

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

  • адрес ресурса;
  • IP-адрес пользователя;
  • дата и время посещения, часовой пояс;
  • GET/POST – запрос на получение или отправку данных;
  • к какой странице обращались;
  • протокол пользователя (как зашел на ресурс);
  • код отклика сервера;
  • число переданных байтов;
  • информация о посетителе (боте) – устройство, ОС, другие данные.

Как правило, такой информации достаточно, чтобы проанализировать ситуацию и сделать нужные выводы. Например, заблокировать бота, который создал чрезмерную нагрузку на сайт.
Файл ошибок (error.log) регистрирует моменты, когда что-то пошло не так. Из них можно узнать:

  • когда произошла ошибка (дата, время), ее тип и IP-адрес пользователя;
  • тип события;
  • где находится сам файл и строка с сообщением

Конечно, даже после расшифровки, данных логов еще нужно проанализировать. Для этого существует различное ПО, которое помогает отрабатывать данные из логов – Weblog Expert, WebAlyzer, Analog, Webtrends, Awstats, SpyLOG Flexolyzer и другие платные и бесплатные программы.

Источник

Понравилась статья? Поделить с друзьями:
  • Как помечается ошибка абзац
  • Как посмотреть какая ошибка была на компьютере
  • Как поменять свидетельство о браке при ошибке
  • Как посмотреть какая была ошибка синего экрана
  • Как поменять миграционную карту если там ошибка