Появилась проблема с обработкой логов

[teddy]

Колеги!
Дано лог файлы формата YYYY-MM-DD.log т.е каждый день создается новый лог файл с событиями. Логи пишутся постоянно, при добавлении новой строки в лог тайм метка файла меняется.
Есть item который ищет строки по регулярке. И в случає нахождения - дает алерт.
настройки item : Zabbix Agent Active, key = logrt[\\server.domain.com\log\*.log, @log_seach_reg1], @log_seach_reg1 = '(.*) error worker(.*)', тригер на стоит на собтытие по условию item <> " ", тип 'Multiple', без условия восстановления, подразумевается только ручное закрытие.
Проблема в том что нужные строки заббікс находит. выводит алерт. Но при дописывания в файл новых строк он с какогото момента стал опять перечитывать файл с начала.
Подчеркну раньше - месяц назад ориентировчно - все работало как задумано. С какого момента сломалось я не заметил вовремя.
И как итог - события повторяются многократно.

Вопрос - я что то сделал неправильно и нужно поправить? или с какойто версии появился такой забавный баг?
версия Zabbix Server 6.4.18/Postgres, Zabbix Client 2 - Win 6.4.7

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

[Kos]

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

• попробовать обновить агента Zabbix на последний релиз для вашей версии. Так, для версии 6.4 последний доступный релиз - это 6.4.21 (ссылка); между релизами 6.4.7 и 6.4.21 было довольно много исправлений - есть шанс, что мог быть исправлен какой-то баг, проявляющийся в вашем случае.
• мониторинг лог-файлов, расположенных на другом сервере и доступных по сети, - это в принципе не очень хорошая практика. Если есть возможность перенести такой мониторинг на сам сервер \\server.domain.com, на котором эти логи и расположены, то это было бы надёжнее. Например, судя по описанию по первой ссылке, в качестве одного из критериев того, что файл поменялся, учитывается изменение его номера inode (или его аналога для агента под Windows - индекса файла и т.п.). Вполне возможно, что в случае сетевых соединений может поменяться файловый дескриптор при, например, реконнекте к серверу.

[teddy]

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

Я вижу варианты причин:
1. моя первая попытка обрабатывать логи на Windows server. Возможно функции типа logrt не работают в Windows или работают с особенностями. На linux таких проблем нет
2. возможно причиной есть то что данный лог "дополняется" именно по сети - есть несколько обработчиков на разных серверах, которые пишут в один лог. и по нему нужен мониторинг. разбить на кучу логов не вариант, т.к основная задача логов - для человеков. доп мониторинг забиксом - скорее контроль чтоб не пропустили.
3. "шара" на котрой лежит файл лога - DFS ресурс а не просто "расшаренная" папка на одном из серверов.

возможно причины все вместе. пока как лечить не понимаю.

[Semiadmin]

Тоже сталкивался с внезапным повторным перечитыванием лога, на разных версиях агента. Кстати, с сервером 6.4 вполне совместим агент 7.0 и 7.2, так что простор для обновления агента есть. Честно говоря, решение не нашел. В качестве обходного решения (это был не постоянный мониторинг логов приложения, а использование заббикса для траблшутинга некой проблемы) добавил в js-препроцессинг сравнение времени в записи с текущим временем и отбрасывание заведомо старых записей.

[teddy]

а каков смысл параметра "Формат времени журнала" ? я расчитывал что именно по такому параметру идет рассчет "метки прочитанного лога". но судя по результату и описанию - нет. а тогда зачем он?

[Semiadmin]

Этот параметр позволяет заполнить поле "Local time", видимое в latest data, датой из записи в логе

[teddy]

мне не удалось включить такой режим.
пример строки лога
11:27:40 test123.ps1:bla bla bla
пример Log time format
h:m:s

результат поле "Local time" пустое. вариант hh:mm:ss аналогично.
у кого есть практика как настроить?

[Kos]

а каков смысл параметра "Формат времени журнала" ? я расчитывал что именно по такому параметру идет рассчет "метки прочитанного лога". но судя по результату и описанию - нет. а тогда зачем он?

Если в настройках элемента данных в поле "Тип информации" указано: "Журнал (лог)", то кроме самих данных (непосредственно прочитанная запись из файла или журнала в Windows Event Log), в базе данных истории (history_log) сохраняются также и некоторые метаданные:

• logeventid
• severity
• source
• timestamp

Что-то из них можно затем преверять с помощью триггерных функций (logeventid(), logseverity(), logsource()), а что-то доступно в виде встроенных макросов ({ITEM.LOG.EVENTID}, {ITEM.LOG.NSEVERITY}, {ITEM.LOG.SEVERITY}, {ITEM.LOG.SOURCE}, {ITEM.LOG.DATE} и {ITEM.LOG.TIME}, см. подробнее здесь).
Так вот, то, о чём вы спрашиваете, позволяет сохранять поле "timestamp" на основе данных, извлекаемых из строки файла. Но это не влияет на стандартные поля "clock" и "ns", которые есть для всех типов данных. Грубо говоря, "timestamp" - это отметка времени, когда данные были записаны в лог, а "clock/ns" - отметка времени, когда эти данные были прочитаны агентом Zabbix.

[Kos]

мне не удалось включить такой режим.
пример строки лога
11:27:40 test123.ps1:bla bla bla
пример Log time format
h:m:s

результат поле "Local time" пустое. вариант hh:mm:ss аналогично.
у кого есть практика как настроить?

Понятие "штамп времени" подразумевает, что указаны и дата, и время. Я не пробовал экспериментировать, когда указано только что-то одно (либо дата, либо время), но когда в строке есть и то, и другое, причём в стабильном формате (под каждое поле отведено конкретное количество знаков), то этот параметр работает корректно. Понятно, что недостаточно гибко (например, нет возможности указать часовой пояс, или что время указано в виде unixtime, или что число месяца может содержать один либо два знака в зависимости от даты), но это лучше, чем ничего.

Вариант "h:m:s" для ваших данных заведомо неверен (у вас используется по два знака для часов, минут и секунд), должно быть "hh:mm:ss"; но повторюсь - возможно, дело в том, что в данном случае для полного штампа времени не хватает даты.

[teddy]

да, спасибо, после смены формата тайм стампа в самом логе ( добавил дату кроме времени) - поле "Local time" стало заполняться. Правда основной проблеме не помогло. все равно алерты многократно дублируються.
Пока есть только идея писать в тег алерта "Local time" и после закрывать кореляцией алерты с одинаковым тегом... но даже звучит такое как то странно.

[teddy]

так работает. но слишком много мусора хоть и закрытого.
прошу помощи с идеями.
может предобработку на javascript сделать? но как получить таймстамп последней обработаной записи _до_ текущей?
может javascript писать в макрос?

[Kos]

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

• писать таймстэмп в начало строки в каком-то формате, удобном для обработки (например, сразу в виде unixtime);
• добавить для элемента данных шаг предобработки с типом JavaScript, в котором извлекать этот таймстэмп из записи и сравнивать с текущим временем сервера (например, Date.now() возвращает аналогичный таймстэмп, но только не в секундах, а в миллисекундах). И, если разница превышает какой-то предел, то генерировать exception, а вторым шагом предобработки проверять на неподдерживаемое значение - и в этом случае просто отбрасывать такое значение.

[teddy]

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

[teddy]

Сделал по указаному Kos способу. Скрипт вышел забавный, т.к время в логах в локали а javascript date() вовращает в UTC. формат времени подправляю предобработкой в regexp, потом уже javascript
если кому-то интересно - могу дать сюда.
для полного феншуя там только не хватает возможности задать через макрос хоста переменную "на какое время отставания в минутах не реагировать".

[teddy]

PS. но вообще то это баг в обработке логов. Не так ли? или кто то не согласен со мной?
возможно уже есть такой тикет?

[Kos]

Скрипт вышел забавный, т.к время в логах в локали а javascript date() вовращает в UTC.

Я потому и предлагал сразу лог писать в формате unixtime, что там пофигу на часовой пояс.
Пользовательские макросы, насколько мне помнится, доступны из JavaScript кода тоже.

PS. но вообще то это баг в обработке логов. Не так ли? или кто то не согласен со мной?
возможно уже есть такой тикет?

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

[teddy]

Ну обрабатывать елементарно. При чтении запоминать счетчик строк\байт которые уже прочитали. если в файле есть строки\байты после запомненой величины - дочитываем пока не закончится файл. и так прикаждой обработке файла ( в случає с ротацией из файла с максимальным timestamp ).
Если текущий размер файла меньше чем запомненое значение - тогда и только тогда начинаем читать с начала файла.
Вообще я был уверен что оно так и работает без привязки к дескрипторам\inode открытых файлов.
Про баг репорт я понял. Попробую сформулировать и написать