Ложное срабатывание триггера после обновления до 4.0.1

[Timka]

Здравствуйте!
Триггер работает уже 2 года, но после обновления стал срабатывать когда не должен.

Триггер:

{MT4 Classic Demo NEW:log["E:\MetaTrader4Server\plugins\mtmonitor_BTC.log","BTCUSD","UTF-8",100].str(trade disabled)}=1 and {MT4 Classic Demo NEW:log["E:\MetaTrader4Server\plugins\mtmonitor_BTC.log","BTCUSD","UTF-8",100].nodata(540)}=1

Данные в заббикс приходят:

22.11.2018 16:01:17    22-11-2018 15:19:05    BTCUSD(BTC) ticks(4525.31000/4563.37000) trade enabled
22.11.2018 16:01:17    22-11-2018 15:06:26    BTCUSD(BTC) timed out, trade disabled
22.11.2018 16:01:17    22-11-2018 12:19:05    BTCUSD(BTC) ticks(4525.31000/4563.37000) trade enabled
22.11.2018 16:01:17    22-11-2018 12:06:26    BTCUSD(BTC) timed out, trade disabled
22.11.2018 16:01:17    22-11-2018 11:52:05    BTCUSD(BTC) ticks(4525.31000/4563.37000) trade enabled
22.11.2018 16:01:17    22-11-2018 11:42:26    BTCUSD(BTC) timed out, trade disabled

Частота проверки установлена на 30 секунд.
По появлению "BTCUSD(BTC) timed out, trade disabled" триггер ждёт 9 минут и если ни чего нет, то должен срабатывать.
Иногда он корректно отрабатывает, но бывает, что как появляется в строке "BTCUSD(BTC) timed out, trade disabled" он сразу сообщает о проблеме и о её восстановлении.
Так же действие на этот триггер ругается на неудачную удалённую команду. В действии только настроено слать сообщение в Telegram и всё.

[Timka]

Снова здравствуйте. Нет ни у кого идей?

[Kos]

О! Коллега, та же проблема: аналогичная ситуация, подобный же триггер, возникла после перехода v3.0.20 -> v4.0.1. Видимо, буду открывать инцидент в техподдержке.

[Timka]

Kos, спасибо за ответ. Откройте пожалуйста.

[Semiadmin]

А если добавить Recovery expression
.str(trade enabled)}=1 ?

[Timka]

Добавил в востановление:

{MT4 Classic Demo NEW:log["E:\MetaTrader4Server\plugins\mtmonitor_BTC.log","BTCUSD","UTF-8",100].str("trade enabled")}=1

Утром напишу как отрабатывал. Когда кидал строки руками в лог, то триггер отрабатывал нормально и в начальном варианте, а вот ночью 20-30 срабатываний.
Спасибо большое!

[Kos]

А если добавить Recovery expression
.str(trade enabled)}=1 ?

Думаю, вряд ли это поможет. Recovery expression влияет только на то, как триггер будет переходить из состояния PROBLEM в состояние OK, а здесь проблема в обратном переходе: он переходит в PROBLEM тогда, когда не должен.
Я инцидент открыл, будем разбираться.

[Timka]

Да, не помогло.

[Timka]

Получилось победить? Можно ссылку на инцидент?
Спасибо.

[Tallo23]

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

[Kos]

Получилось победить? Можно ссылку на инцидент?
Спасибо.

Нет, пока что не получилось, всё ещё разбираемся.
Ссылка на инцидент (номер инцидента - GL-150) вряд ли что-то вам даст (кроме возможности сослаться на неё при обращении в техподдержку), т.к. конкретный инцидент доступен только клиенту и техподдержке, но не публично.

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

Последнее, что удалось нащупать, - это то, что проблему легко воспроизвести, если в настройках агента умышленно "задрать" значение параметра "BufferSend=" до трёх минут (поставить 180 или 200).

[Timka]

Kos, будем ждать. Спасибо за полный ответ! Отпишитесь тут пожалуйста как разберётесь.

[Kos]

Отписываюсь о состоянии на данный момент. Как поётся в песенке, "всё куда интеллигентней и намного веселей" :-)
Т.е. в процессе разбирательств вскрылось несколько неочевидных вещей, в том числе баги (зачёркнуто) особенности, которые работают неправильно уже годами :-/
Далее будет, наверное, немного длинно и занудно, уж извините.

Упирается всё в особенности работы агента Zabbix в активном режиме под Windows. Я чуть выше писал:

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

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

Следующий момент - до версии 4.0 в Zabbix-серверах и Zabbix-прокси был механизм, который мог корректировать таймстэмпы отдельных значений на основе разницы текущего времени на сервере или прокси и таймстэмпа пересылаемой "пачки" значений. См. последний комментарий "Timestamps", например, здесь, который в версии 4.0 был убран: несмотря на упоминание лишь утилиты zabbix_sender, тот же механизм работал и для агента в активном режиме (они с zabbix_sender-ом используют один протокол передачи данных на сервер). После долгих совещаний этот механизм в версии 4.0 был выкинут вообще (основная аргументация: Zabbix должен хорошо выполнять свою основную задачу, а не пытаться совмещать в себе ещё и функционал других подсистем). Дескать, сервер должен, как джентльмен, верить агенту на слово, а для синхронизации времени есть, например, NTP - им и пользуйтесь.

Однако после этого выяснилось, что упомянутый механизм как раз, в числе прочего, компенсировал уплывание "неправильного" таймера на Windows-агентах. И теперь, когда этот механизм убран, проблема с уплыванием таймера, незаметная раньше, встала во всей красе: чем дольше агент работает без рестарта, тем сильнее это разбегание. Особенно экзотично это выглядит, когда упомянутый таймер отстаёт, а сами значения собираются правильно. Например, в моём случае выглядело так, как будто данные считываются из лог-файла раньше, чем они туда попадают :-) Скажем, якобы в 08:00:00 считываются строки лога, в которых написано, что они туда помещены в 08:00:14.

А далее - при обработке данных на сервере Zabbix в большинстве случаев учитывается не текущее время сервера, а именно тайстэмп пришедшего значения. Особенно интересно получается для метрики system.localtime, для которой by design таймстэмп всегда должен совпадать с её значением; как следствие - использовать триггерную функцию fuzzytime() при работе агента в активном режиме просто бесполезно (о чём теперь втихаря появились пометки и в описании этой функции, и в описании этой метрики, но только в документации версии 4.0).
И, весьма похоже, что и для функции nodata() происходит то же самое: приходит значение с таймстэмпом "три с половиной минуты назад", и функция nodata(180) срабатывает. Перезапускаешь агента Zabbix - какое-то время работает нормально, потом (когда разбегание часов превысит определённое пороговое значение) ложные срабатывания начинаются снова.

Вкратце - текущая ситуация:

• Проблема с таймером для Windows-агента решается в рамках ZBX-15301, по указанной ссылке доступны (как аттачменты) скомпилированные агенты под Windows (для желающих попробовать "здесь и сейчас"). Исправления войдут в версию Zabbix 4.0.4. Все агенты предыдущих версий подвержены этой проблеме! Однако, проблема специфична: а) для активного режима работы агента, б) для платформы Windows.
• Написан баг-репорт с просьбой привести поведение триггерной функции fuzzytime() в соответствие с документацией, т.е. сравнивать значения именно с текущим временем на сервере Zabbix, а не с чем-либо ещё. Тогда её можно будет использовать и при работе агента в активном режиме тоже.

[Timka]

День добрый! Обновился вчера до 4.0.4 - проблема осталась
Более того, иногда теперь в элемент приходят передыдущие значения позже новых. И триггер соответственно висит в проблеме.
Пример:

 [TABLE="class: list-table"]
[TR]
[TD="class: nowrap"]14.02.2019 08:34:18[/TD]
 			[TD] [/TD]
 			[TD]14-02-2019 08:34:02 EURUSD(EURUSD) timed out, trade disabled[/TD]
 		[/TR]
[TR]
[TD="class: nowrap"]14.02.2019 08:34:18[/TD]
 			[TD] [/TD]
 			[TD]14-02-2019 08:34:12 EURUSD(EURUSD) ticks(1.12759/1.12773) trade enabled[/TD]
 		[/TR]
[/TABLE]

PS. Kos, спасибо за подробный ответ.

[Kos]

День добрый! Обновился вчера до 4.0.4 - проблема осталась

Добрый день!
Обновили агента или сервер? По идее, если сервер версии 4.x (любой), то нужно обновлять агента до версии минимум 4.0.4 (недавно официально выложен).