Обновление до 2204

Georg · May 26, 2022, 8:16pm

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

26-05-2022 17:50:03.166 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 4 counter of device wb-mr6c_154: Invalid value of type value @ wblib/control.cpp:512
26-05-2022 17:50:03.166 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 4 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:03.166 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 1 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:03.166 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 3 counter of device wb-mr6c_154: Invalid value of type value @ wblib/control.cpp:512
26-05-2022 17:50:03.166 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 2 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:03.166 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 5 counter of device wb-mr6c_154: Invalid value of type value @ wblib/control.cpp:512
26-05-2022 17:50:03.166 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 3 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:03.166 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 0 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:02.851 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 2 counter of device wb-mr6c_154: Invalid value of type value @ wblib/control.cpp:512
26-05-2022 17:50:02.851 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control K1 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:02.851 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 0 counter of device wb-mr6c_154: Invalid value of type value @ wblib/control.cpp:512
26-05-2022 17:50:02.851 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control K4 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:02.851 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 1 counter of device wb-mr6c_154: Invalid value of type value @ wblib/control.cpp:512
26-05-2022 17:50:02.851 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 5 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:02.851 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 6 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:02.851 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Input 6 counter of device wb-mr6c_154: Invalid value of type value @ wblib/control.cpp:512
26-05-2022 17:50:02.851 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control K2 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:02.851 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control K3 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:02.457 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control K5 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:02.457 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control K6 of device wb-mr6c_154: Invalid value of type switch @ wblib/control.cpp:512
26-05-2022 17:50:02.457 [wb-mqtt-db.service]	ERROR: [driver] failed to accept new meta order on control Serial of device wb-mr6c_154: Invalid value of type text @ wblib/control.cpp:512

Что это за ошибка - она почти на всех устройствах в системе

Georg · May 28, 2022, 1:49pm

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

релиз криво поставился
за два дня релизобновили и что-то подлатали.

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

28-05-2022 16:28:01.866 [rsyslog]	Child 21539 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]
28-05-2022 16:23:23.432 [rsyslog]	Child 20837 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]
28-05-2022 16:18:48.312 [rsyslog]	Child 20155 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]
28-05-2022 16:14:07.093 [rsyslog]	Child 19432 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]
28-05-2022 16:09:28.562 [rsyslog]	Child 18719 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]
28-05-2022 16:04:53.219 [rsyslog]	Child 18044 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]
28-05-2022 16:04:53.219 [rsyslog]	Child 18044 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]
28-05-2022 16:00:18.505 [rsyslog]	Child 17345 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]

оччень много

Georg · May 30, 2022, 2:53pm

кто-нибудь может объяснить что это значит

EvgenyBoger · May 30, 2022, 11:13pm

Добрый день!

Сформулируйте пожалуйста вопрос чуть точнее. Я из сообщений так и не понял, какие записи появились, какие пропали, и что вы хотите узнать.
Пожалуйста приложите диагностический архив, его можно скачать из веб-интерфейса.
Случайный кусок лога без контекста почти всегда бесполезен. Лог лучше прикладывать целиком. В диагностическом архиве он уже есть.

Georg · May 31, 2022, 7:58am

Евгений, большое спасибо за ответ,
постараюсь объяснить суть вопроса

Предыстория:
при загрузке правил в контроллер, они проходили проверку (при нажатии кнопки “сохранить” ошибок не было) но контроллер подвисал, sftp переставало работать, правила не выполнялись. Поддержка рекомендовала внимательно СМОТРЕТЬ ЛОГИ. Это помогло, вопрос был решен.

Касательно логов:
Полностью разобраться самому не получилось. Обновил на 2204, удалил из контроллера все правила, в системном журнале выделил только критические и серьёзные ошибки. Вот с этим логом я и обратился в поддержку.
Сегодня утром решил поменять 2204 на тестовую 04110. В логах мало что изменилось.

Затем пришло сообщение от вас.

Вопрос в том, как в “чистом” , без правил, устройстве (с подключенными корректно модулями), в логах могут быть критические и серьёзные ошибки.
диагностический архив - прикладываю
diag_output_A7ZQVZMS_2022-05-31-10.44.19.zip (77.3 КБ)
Согласен. Но в данном случае лог выложен полностью. после обновления релиза и команды reboot.
Не хочется жить по принципу - “не ходишь к врачу - значит не болеешь”.
Я понимаю, что часть ошибок про блютус и ррр можно смело пропустить, но хотелось бы знать, что происходит в чистой системе перед тем как начинать в неё грузить свои правила.
Непонятки с rsyslog каждые 5 минут тоже настораживают.
Вот полный лог ( выбрано только emergency,alert,critical,error) после обновления на 04110 после перезагрузки

-----------------------**

31-05-2022 10:03:03.181 [rsyslog] Child 15104 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:59:00.714 [rsyslog] Child 14406 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:54:58.557 [rsyslog] Child 13755 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:50:57.145 [rsyslog] Child 13095 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:46:55.372 [rsyslog] Child 12442 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:42:54.288 [rsyslog] Child 11758 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:38:53.991 [rsyslog] Child 11112 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:34:49.471 [rsyslog] Child 10455 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:30:48.987 [rsyslog] Child 9797 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:26:46.959 [rsyslog] Child 9146 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:26:46.959 [rsyslog] Child 9146 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:22:49.545 [rsyslog] Child 8498 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:18:45.204 [rsyslog] Child 7278 has terminated, reaped by main-loop. [v8.24.0 try http://www.rsyslog.com/e/0 ]**
31-05-2022 09:13:51.170 [wb-mqtt-knx] ERROR: [knx] Error in KNX loop: Failed to get a group TPDU: Connection reset by peer**
31-05-2022 09:13:34.882 [ntp] unable to create socket on wlan0 (6) for fe80::7e25:daff:fe1f:5a25%5#123**
31-05-2022 09:13:34.781 [ntp] bind(25) AF_INET6 fe80::7e25:daff:fe1f:5a25%5#123 flags 0x11 failed: Cannot assign requested address**
31-05-2022 09:13:16.618 [bluetooth] sap-server: Operation not permitted (1)**
31-05-2022 09:13:16.600 [bluetooth] Sap driver initialization failed.**
31-05-2022 09:13:16.580 [bluetooth] Failed to obtain handles for “Service Changed” characteristic**
31-05-2022 09:13:10.318 usb usb1-port1: over-current condition**
31-05-2022 09:13:10.318 usb usb1-port1: over-current condition**
31-05-2022 09:13:05.846 imx6ul-pinctrl 2290000.iomuxc-snvs: no groups defined in /soc/bus@2200000/iomuxc-snvs@2290000**
31-05-2022 09:13:05.843 debugfs: Directory ‘dummy-iomuxc-gpr@20e4000’ with parent ‘regmap’ already present!**
31-05-2022 09:12:51.551 watchdog: watchdog0: watchdog did not stop!**
31-05-2022 09:12:42.280 [init.scope] watchdog.service: Failed to enqueue OnFailure= job: Resource deadlock avoided**
31-05-2022 09:12:40.612 caught signal 15 - exiting**
31-05-2022 09:12:34.972 [wb-mqtt-db.service] ERROR: [driver] failed to accept new meta “order” on control “data” of device “knx”: Invalid value “” of type “text” @ wblib/control.cpp:512**
-------------------------*

BrainRoot · May 31, 2022, 4:02pm

Добрый день.
rsyslog ведет себя совершенно нормально при ротации. Подозрительно часто - но откуда у вас такой инкремент номеров процессов за такой малый период? это по 500 процессов в минуту запускается.

А что туда подключено?

Georg · May 31, 2022, 6:01pm

Да ничего туда не подключено!!!
работает только один порт - ethernet
причем для чистоты эксперимента отключил конвертор WB-MIO-E v.2
все остальные устройства видно в конфиге.
Все собрано на щите, входы-выходы не подключены, пока пишу правила.

EvgenyBoger · May 31, 2022, 10:32pm

Если честно, я всё ещё не до конца понимаю, чем именно мы можем помочь.
Я правильно понимаю, что причина обращения по формуле обращения такая:

Делаю: открываю лог с ошибками (emergency,alert,critical,error)
Ожидаю: пустой лог, потому что система прекрасно работает
Получаю: не пустой лог, в нём есть сообщения от rsyslog и другие непонятные
?
Я вас правильно же понял?

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

По приведённому логу:

rsyslog просто ротируется и слишком громко ругается, как выше написал коллега. Почему он ротируется так часто? Потому что у вас включен debug в сервисе wb-mqtt-serial и он генерирует огромное количество отладочных сообщений.
вторая половина лого про проблемы с сетью. Скорее всего этот кусок захватывает сам процесс обновления, в процессе которого обновлялся какой-то сетевой компонент и перезапускалась сеть. Все эти сообщения - про временную невозможность какого-то из сервисов куда-то подключиться.
imx6ul-pinctrl 2290000.iomuxc-snvs: no groups defined in /soc/bus@2200000/iomuxc-snvs@2290000 и подобное - можно смело игнорировать. Если научитесь воспроизводить такие сообщения - пожалуйста напишите нам, попробуем убрать
usb usb1-port1: over-current condition - это точно баг у нас, железо не умеет определять over-current condition (хоть и умеет аппаратно ограничивать ток). Поправим, чтобы не ругалось.

Georg · June 1, 2022, 9:32am

Добрый день, Евгений
спасибо за уделённое время
Вы меня абсолютно правильно поняли, я пытаюсь разобраться что происходит с системой,
потому что меню “Настройка драйвера serial-устройств” открывается почти 80 секунд!
А по SFTP иногда не выполняется подключение - после автоматичкого ввода пароля - зависание и отключение. Значит что-то не так.
Поэтому к логам не академический интерес, а практический.
На текущий момент debug в сервисе wb-mqtt-serial - выключил - rsyslog успокоился.
Насчёт сети - modbus over ethernet - сконфигурен, но в настройках портов отключен.
Мешать не должен. Что касается логов - сейчас сообщений меньше.

01-06-2022 11:45:11.423 [wb-mqtt-knx] ERROR: [knx] Error in KNX loop: Failed to get a group TPDU: Connection reset by peer
01-06-2022 11:44:50.849 [ntp] unable to create socket on wlan0 (6) for fe80::7e25:daff:fe1f:5a25%5#123
01-06-2022 11:44:50.009 [ntp] bind(25) AF_INET6 fe80::7e25:daff:fe1f:5a25%5#123 flags 0x11 failed: Cannot assign requested address
01-06-2022 11:44:33.780 [bluetooth] sap-server: Operation not permitted (1)
01-06-2022 11:44:33.763 [bluetooth] Sap driver initialization failed.
01-06-2022 11:44:33.743 [bluetooth] Failed to obtain handles for “Service Changed” characteristic
01-06-2022 11:44:26.568 usb usb1-port1: over-current condition
01-06-2022 11:44:21.857 imx6ul-pinctrl 2290000.iomuxc-snvs: no groups defined in /soc/bus@2200000/iomuxc-snvs@2290000
01-06-2022 11:44:21.854 debugfs: Directory ‘dummy-iomuxc-gpr@20e4000’ with parent ‘regmap’ already present!
01-06-2022 11:44:06.805 watchdog: watchdog0: watchdog did not stop!
01-06-2022 11:44:06.805 watchdog: watchdog0: watchdog did not stop!
01-06-2022 11:44:06.199 [init.scope] Failed unmounting /var/log.
01-06-2022 11:44:02.782 caught signal 15 - exiting

лог после перезагрузки - в 11:44 была команда reboot из консоли.
Кстати конфиг wb-mqtt-serial после одного из последних обновлений был заново введен через форму вручную. Может задержка зависит от количества устройств и я зря переживаю.

BrainRoot · June 1, 2022, 10:21am

Какое количество устройств в wb-mqtt-serial.conf (дайте файл) какая нагрузка на cpu (например) в момент входа?

Georg · June 1, 2022, 10:54am

Если я правильно смотрю - в разных окнах “хрома”
то при загрузке конфига в одном окне, в другом окне
load_average_1min от 1,6 до 2,25 . так?
Устройства модбас на трёх шинах 4+3+3 . всего десять.
из них 9 шт. WB и одна панель Cityron ПУ-3.

BrainRoot · June 1, 2022, 10:56am

Так, а какие процессы занимают больше всех ресурсов?
Ну и файл wb-mqtt-serial все ж выложите.

Georg · June 1, 2022, 11:13am

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

вроде норм, только кратковременно загрузка доходила до 70%

сам конфиг вот

wb-mqtt-serial.conf (6.6 КБ)

BrainRoot · June 1, 2022, 1:23pm

Загружается за 7-10 секунд.
Нормальная ли связь между контроллером и компьютером?

Georg · June 1, 2022, 2:03pm

В одном свиче цыско - в разных помещениях, длина линий до свича не более 5 метров.
пинг 1-2 ms

ping

BrainRoot · June 1, 2022, 2:19pm

Так, а если перед редактированием остановить сервисы wb-rules и wb-mqtt-serial, чтобы освободить процессор? Десяток секунд на загрузку в принципе норма, но болше минуты - это явно много.

Georg · June 1, 2022, 2:45pm

остановил

72 секунды! с отлюченными сервисами wb-rules и wb-mqtt-serial

BrainRoot · June 1, 2022, 3:12pm

Ну, это чудо какое-то. В браузере включите отдадку, у меня около 11 секунд на чтение с контроллера по ws всего содержимого конфига.

Georg · June 3, 2022, 9:12am

Доброго дня
отладка похоже липовая (ну или я что-то не так измеряю)
хром показывает 18 секунд, едж … по разному, то 16, то 6 секунд.
реально все те же 75-80 секунд!
Попробую по частям (вернее по портам) прогнать конфиг, может найдется затычка.
…
отключил все порты - результат отрицательный - копаем дальше
…
заменил рабочий конфиг дефолтным - вообще без устройств! - время загрузки - 32 секунды.
что еще почистить))), может удалить панели, пока не нашел где они лежат.

Haggard · June 3, 2022, 7:41pm

Добрый вечер,

На 6,8 так же заметил увеличение время открытия /etc/wb-mqtt-serial.conf в браузере.
35 устройств, 80-100 сек.

load_average_1min 3.03 tasks
load_average_5min 3.19 tasks
load_average_15min 2.84 tasks

Node Red из стороннего, все правила на нем работают.

 1623 root      20   0   81220  12000   6540 S 21.0  1.2   5:41.95 wb-mqtt-serial
  635 root      25   5  338348 257396  28936 R 14.0 25.1   5:21.58 node
 1622 root      20   0  911676  22812  11316 S 11.0  2.2   3:11.95 wb-rules
 1653 root      20   0   62276   8880   5400 S  5.8  0.9   1:32.19 main
  613 mosquit+  20   0    9352   6104   3864 S  4.0  0.6   1:29.11 mosquitto
 6720 root      20   0    5524   2488   1944 R  1.8  0.2   0:27.77 top
 1646 root      20   0   23432  11604   5688 S  1.5  1.1   0:18.36 wb-metrics
 6452 root      20   0   59464   6380   5620 S  1.5  0.6   0:23.11 wb-mqtt-gpio

wb-mqtt-serial (3).conf (17.2 КБ)