Некорректное значение map6e

paulstrong · 06.Июль.2023 21:20:30

добрый день!
в апреле настроил сбор метрик из map6e при помощи telegraf в базу influxdb
всё собирается исправно, но в базе встречаются единичные аномальные значения, вот пример.
я выбрал все значения за июнь по топику /devices/wb-map12e_14/controls/Ch 1 Total AP energy

1687169751631304646 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 75.77961
1685566800458635749 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84889
1685566801511745128 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84895
1685566802569793310 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84902
1685566803574522290 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84907
1685566804651347847 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84914
1685566805660690295 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84921
1685566806731180713 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84926
1685566807750137600 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84933
1685566808725560973 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84938
1685566809797949603 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84945
1685566810782137371 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.8495
1685566811819383090 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84957
1685566812830476459 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84962
1685566813871084269 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84969
1685566814876810084 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84976
1685566815872490711 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84981
1685566816862676617 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84987
1685566817885704929 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.84993
1685566818995710643 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.85
1685566820057491875 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.85007
1685566821101028858 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.85013
1685566822158789080 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.85019
1685566823120877549 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.85025
1685566824128563327 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.85032
1685566825116286395 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.85037
1685566826149380146 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 369.85044

отсортировал по значению и вывел первые 30
видно что в понедельник, 19 июня 2023 г., 13:15:51.631 [GMT+03:00] в топике было значение 75.77961

вот как это выглядит в ряду значений без сортировки

1687168765615331276 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63328
1687168766580863136 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63361
1687168767634110552 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63401
1687168768720849428 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63442
1687168769733348157 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63474
1687168770693416879 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63514
1687168771721721982 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63547
1687169750048834932 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.54793
1687169751631304646 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 75.77961
1687169760140400183 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63739
1687169761503140466 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63743
1687169762510018140 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63745
1687169763529343595 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63749
1687169764546086543 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63751
1687169765625259941 orangepi3-lts /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63755

если перевести timestamp в дату, то так лучше видно проблемное место

2023-06-19 12:59:25 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63328
2023-06-19 12:59:26 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63361
2023-06-19 12:59:27 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63401
2023-06-19 12:59:28 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63442
2023-06-19 12:59:29 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63474
2023-06-19 12:59:30 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63514
2023-06-19 12:59:31 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63547
2023-06-19 13:15:50 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.54793
2023-06-19 13:15:51 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 75.77961
2023-06-19 13:16:00 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63739
2023-06-19 13:16:01 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63743
2023-06-19 13:16:02 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63745
2023-06-19 13:16:03 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63749
2023-06-19 13:16:04 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63751
2023-06-19 13:16:05 /devices/wb-map12e_14/controls/Ch 1 Total AP energy 474.63755

в 12:59:31, видимо, отключалось электричество, в 13:15:50 метрика снова появилась, видимо, электричество включили обратно, но при этом значение было меньше чем до выключения, хоть и несущественно, а дальше в 13:16:00 уже значение 75, что существенно меньше.

в связи с этим вопрос: как могло произойти такое? почему значение у счётчика уменьшилось? это же теоретически не должно быть возможным.

BrainRoot · 07.Июль.2023 14:28:17

Добрый день.

Так, но запись в базу - это уже окончательный этап путешествия данных.
То есть счетчик-modbus-mqtt-telegraf-influx
На этапе modbus-mqtt если что-то шло не так можно спросить логи.
А нет ли логов (в принципе должны еще остаться) wb-mqtt-serial за указанное время?

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

paulstrong · 07.Июль.2023 15:58:50

в БД контроллера хранится статистика за 3 дня максимум
логи посмотрел - тоже не осталось уже ничего.
ясно, вобщем пока что объяснения нет

BrainRoot · 07.Июль.2023 16:23:41

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

paulstrong · 09.Июль.2023 10:04:05

OK! хорошая идея, сделаю так.

paulstrong · 11.Июль.2023 11:38:41

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

var telegram = require("telegram"); 
var ps = new PersistentStorage("virtual-test-device-storage", {global: true});


defineRule("wb-map12e_14/Ch 1 Total AP energy", {
  whenChanged: "wb-map12e_14/Ch 1 Total AP energy",
  then: function (newValue, devName, cellName) {
      if(ps['s14ch1'] !== 0 && !ps['s14ch1']){
          ps['s14ch1'] = newValue
          var msg = "значение устройства {} (канал {}) проинициализировано впервые - {}".format(devName, cellName, ps['s14ch1'])
          telegram.SendMessage(msg)
      }
      if (newValue >= ps['s14ch1']){
          ps['s14ch1'] = newValue
      } else {
          var msg = "значение устройства {} (канал {}) уменьшилось, было {}, стало {}".format(devName, cellName, ps['s14ch1'], newValue)
          telegram.SendMessage(msg)
      }
  }
});

и так далее по всем каналам
в итоге послали в ребут щит с оборудованием и через минуту включили, я выдернул из системы лог с включенным дебагом. вот ссылка на него mqtt.log.gz — Яндекс Диск
ребут произошёл в Jul 11 14:12:46, смотрите строчку 326271 и далее.

собственно, что я увидел в телеграм канале:

то есть, получается, что при рестарте железки в топике реально возникает малое значение, правда потом оно, судя по всему, восстанавливается, прошу подтвердить или опровергнуть это утвереждение.

спасибо!

BrainRoot · 11.Июль.2023 15:36:10

Со включенным Debug все записи которые в MQTT драйвер делают в нем и отражаются.
Что интересно, поиск по подстроке Ch 1 Total AP energy’ of device 'wb-map12e_14 с момента запуска драйвера выдает первое

Jul 11 14:14:55 wirenboard-AGOQTP4Y wb-mqtt-serial[2270]: DEBUG: [serial port driver] channel 'Ch 1 Total AP energy' of device 'wb-map12e_14' <-- 589.93451, error: ""

И это значение - не 75.77961
То есть на момент запуска wb-mqtt-serial у mqtt откуда-то было значение…
Пока не знаю как воспроизвести. Нет никаких правил которые пишут в MQTT?
Еще вариант - добавить правило, которое с помощью trackMQTT подписывается на корень устройства /devices//wb-map12e_14 и пишет в лог все что в него публикуется.

AlexandrD · 11.Июль.2023 17:06:30

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

paulstrong · 12.Июль.2023 11:43:53

правил, пишущих в mqtt - нет, единственные правила, которые есть, это те, что я создал для логирования в телеграм.
добавил правила trackMqtt, вот tgz с логами, тут греп по wb-mqtt-serial и отдельно греп по wb-rules - logs.tgz — Яндекс Диск
вот время ребута:

Jul 12 14:27:44 wirenboard-AGOQTP4Y wb-rules[2598]: INFO: [rule info] trackMqtt INFO => {"topic":"/devices/wb-map12e_14/controls/Ch 1 Total AP energy","value":"599.34107"}
Jul 12 14:27:45 wirenboard-AGOQTP4Y wb-rules[2598]: INFO: [rule info] trackMqtt INFO => {"value":"599.34129","topic":"/devices/wb-map12e_14/controls/Ch 1 Total AP energy"}
Jul 12 14:29:53 wirenboard-AGOQTP4Y wb-rules[2571]: INFO: [rule info] trackMqtt INFO => {"topic":"/devices/wb-map12e_14/controls/Ch 1 Total AP energy","value":"599.10719"}
Jul 12 14:29:54 wirenboard-AGOQTP4Y wb-rules[2571]: INFO: [rule info] trackMqtt INFO => {"topic":"/devices/wb-map12e_14/controls/Ch 1 Total AP energy","value":"75.77961"}
Jul 12 14:30:05 wirenboard-AGOQTP4Y wb-rules[2571]: INFO: [rule info] trackMqtt INFO => {"topic":"/devices/wb-map12e_14/controls/Ch 1 Total AP energy","value":"599.357"}

paulstrong · 12.Июль.2023 11:45:06

по совету от @BrainRoot включил trackMqtt, потом сделал диагностический архив, прикладываю - diag_output_AGOQTP4Y_2023-07-12-14.22.50.zip — Яндекс Диск
также сделал его еще раз после ребута, когда проблема в очередной раз воспроизвелась - diag_output_AGOQTP4Y_2023-07-12-14.36.55.zip — Яндекс Диск
вдруг в динамике что-то видно будет

paulstrong · 12.Июль.2023 11:47:10

обращу внимание, что я каждый раз наблюдаю одно и то же, сразу после ребута значение почти правильное (незначительно меньше предыдущего), затем через секунду - уже некорректное (причем оно одинаковое всегда 75.77961, но у каждого топика своё неправильное), потом 8-10 секунд временной провал (всегда), и далее уже пошли корректные значения

BrainRoot · 12.Июль.2023 13:10:49

Призвал разработчиков. У меня что-то идеи кончились.

PeteK · 19.Июль.2023 10:53:57

Я правильно вас понимаю, что при перезагрузке контроллера, пропадает питание и на счётчиках?
Если сделать systemctl restart wb-mqtt-serial, тоже будет скачёк?
Не могли бы вы прислать файл /var/lib/wb-mqtt-serial/libwbmqtt.db

paulstrong · 19.Июль.2023 11:25:33

да, правильно, счётчики обестачиваются вместе с контроллером
при рестарте сервиса wb-mqtt-serial скачка не наблюдаю, а вот если рестартнуть wb-mqtt-serial mosquitto, тогда в телеграм прилетают отбивки о том, что значение уменьшилось, провал не большой, но он есть

также попробовал просто ребутнуть контроллер, отбивок в телеграм тоже не было

3.libwbmqtt.db.gz — Яндекс Диск

PeteK · 19.Июль.2023 11:42:57

Архив не распаковывается, можете перезалить?

paulstrong · 19.Июль.2023 12:17:25

так это не архив, это сжатый файл, утилитой gzip
вот несжатая версия
libwbmqtt.db (52 КБ)

PeteK · 19.Июль.2023 12:45:57

Можете ещё перезапустить всё, чтоб был скачёк.
Потом выполнить journalctl -b -u wb-mqtt-serial > log.txt и прислать файл нам.
Кажется, что проблема не в сервисе wb-mqtt-serial.

paulstrong · 21.Июль.2023 13:29:58

PeteK · 24.Июль.2023 10:28:53

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

paulstrong · 24.Июль.2023 13:29:00

то есть тикет закрываем, вы приняли меры?