WB6 виснет при перезагрузке

Dmitry_Matsnev · 27.Июль.2022 18:36:36

Вчера после перехода на ветку testing удаленно перезагрузил контроллер, после чего он “умер” на полчаса, в логах следующее:

июл 26 20:19:16 wirenboard-AUPZT7SN systemd[1]: Stopped target Remote File Systems.
июл 26 20:19:17 wirenboard-AUPZT7SN wb-mqtt-serial[20668]: **WARNING: [backend] Unable to cleanup topic '/devices/mr6_01/controls/Input 4/meta/order': timed out**
июл 26 20:19:17 wirenboard-AUPZT7SN wb-mqtt-serial[20668]: wb-mqtt-serial: wblib/mqtt.cpp:307: virtual WBMQTT::TFuture<void> WBMQTT::TMosquittoMqttClient::PublishSynced(const WBMQTT::TMqttMessage&): Assertion `Connected.load()' failed.
июл 26 20:19:17 wirenboard-AUPZT7SN systemd[1]: **wb-mqtt-serial.service: Main process exited, code=killed, status=6/ABRT**
июл 26 20:19:17 wirenboard-AUPZT7SN systemd[1]: Stopped MQTT Driver for serial devices.
июл 26 20:19:17 wirenboard-AUPZT7SN wb-mqtt-gpio[24955]: **WARNING: [backend] Unable to cleanup topic '/devices/wb-gpio/controls/EXT1_IN10/meta/readonly': timed out**
июл 26 20:19:17 wirenboard-AUPZT7SN wb-mqtt-gpio[24955]: wb-mqtt-gpio: wblib/mqtt.cpp:307: virtual WBMQTT::TFuture<void> WBMQTT::TMosquittoMqttClient::PublishSynced(const WBMQTT::TMqttMessage&): Assertion `Connected.load()' failed.
июл 26 20:19:17 wirenboard-AUPZT7SN systemd[1]: **wb-mqtt-serial.service: Unit entered failed state.**
июл 26 20:19:17 wirenboard-AUPZT7SN systemd[1]: **wb-mqtt-serial.service: Failed with result 'signal'.**
июл 26 20:19:17 wirenboard-AUPZT7SN systemd[1]: **wb-mqtt-gpio.service: Main process exited, code=killed, status=6/ABRT**
июл 26 20:19:17 wirenboard-AUPZT7SN systemd[1]: Stopped MQTT Driver for GPIO-controlled switches.
июл 26 20:19:17 wirenboard-AUPZT7SN systemd[1]: **wb-mqtt-gpio.service: Unit entered failed state.**
июл 26 20:19:17 wirenboard-AUPZT7SN systemd[1]: **wb-mqtt-gpio.service: Failed with result 'signal'.**
июл 26 20:19:17 wirenboard-AUPZT7SN systemd[1]: Stopped Initialize Wiren Board Device Tree overlays.
июл 26 20:19:17 wirenboard-AUPZT7SN systemd[1]: Stopping watch config files...
июл 26 20:19:17 wirenboard-AUPZT7SN systemd[1]: Stopped watch config files.
июл 26 20:49:12 wirenboard-AUPZT7SN systemd[1]: **reboot.target: Job reboot.target/start timed out.**
июл 26 20:49:12 wirenboard-AUPZT7SN systemd[1]: **Timed out starting Reboot.**
июл 26 20:49:12 wirenboard-AUPZT7SN systemd[1]: **reboot.target: Job reboot.target/start failed with result 'timeout'.**
июл 26 20:49:12 wirenboard-AUPZT7SN systemd[1]: **Forcibly rebooting: job timed out**
июл 26 20:49:12 wirenboard-AUPZT7SN systemd[1]: **Shutting down.**
июл 26 20:49:12 wirenboard-AUPZT7SN systemd[1]: Hardware watchdog 'imx2+ watchdog', version 0
июл 26 20:49:12 wirenboard-AUPZT7SN systemd[1]: Set hardware watchdog to 10min.
июл 26 20:49:12 wirenboard-AUPZT7SN kernel: **watchdog: watchdog0: watchdog did not stop!**
июл 26 20:49:12 wirenboard-AUPZT7SN systemd-shutdown[1]: Sending SIGTERM to remaining processes...
июл 26 20:49:12 wirenboard-AUPZT7SN systemd-journald[110]: Journal stopped
**-- Reboot --**
июл 26 20:50:57 wirenboard-AUPZT7SN kernel: Booting Linux on physical CPU 0x0
июл 26 20:50:57 wirenboard-AUPZT7SN kernel: **Linux version 5.10.35-wb116 (jenkins@wbdevenv) (arm-linux-gnueabihf-gcc (Debian 6.3.0-18) 6.3.0 20170516, GNU ld (GNU Binutils for Debian) 2.28) #1 Wed Jul 6 16:10:09 UTC 2022**

Сегодня приехал, подключился к консоли и пытался воспроизвести. Из шести перезагрузок такое поведение повторилось лишь два раза. Как было раньше - не знаю, до этого soft reset делал лишь пару раз, в основном были hard reset.

После нескольких перезагрузок замечено следующее:

Проблема зависания плавающая, все перезагрузки ведут себя по-разному. Это субъективное ощущение, которое складывается из увиденного на консоли и времени старта всех сервисов.
Не каждая загрузка приводит к появлению приглашения на консоли, как на этом скриншоте:

Очень долго, не с первого раза, стартует wb-mqtt-gpio, при этом на консоли:
(скриншот для случая, когда приглашение на консоли так и не появилось)

при этом в логах:

Jul 27 19:12:08 wirenboard-AUPZT7SN systemd[1]: wb-mqtt-gpio.service: Start-pre operation timed out. Terminating.
Jul 27 19:12:08 wirenboard-AUPZT7SN systemd[1]: Failed to start MQTT Driver for GPIO-controlled switches.
Jul 27 19:12:08 wirenboard-AUPZT7SN systemd[1]: wb-mqtt-gpio.service: Unit entered failed state.
Jul 27 19:12:08 wirenboard-AUPZT7SN systemd[1]: wb-mqtt-gpio.service: Failed with result 'timeout'.
Jul 27 19:12:09 wirenboard-AUPZT7SN systemd[1]: wb-mqtt-gpio.service: Service hold-off time over, scheduling restart.
Jul 27 19:12:09 wirenboard-AUPZT7SN systemd[1]: Stopped MQTT Driver for GPIO-controlled switches.
Jul 27 19:12:09 wirenboard-AUPZT7SN systemd[1]: Starting MQTT Driver for GPIO-controlled switches...

пока не стартанул wb-mqtt-gpio, wb-mqtt-serial ругается, почему-то только на один, rs-485:

wb-mqtt-serial[2150]: **WARNING: </dev/ttyMOD1 9600 8 N 2>: closed due to repetetive errors**

После последней загрузки не поднялся модем 4G,

wb-gsm restart_if_broken

зацикливается на:

Jul 27 19:17:37 wirenboard-AUPZT7SN chat[18583]: send (AT^M)
Jul 27 19:17:37 wirenboard-AUPZT7SN chat[18583]: expect (OK)
Jul 27 19:17:42 wirenboard-AUPZT7SN chat[18583]: alarm
Jul 27 19:17:42 wirenboard-AUPZT7SN chat[18583]: Failed
Jul 27 19:18:29 wirenboard-AUPZT7SN chat[18959]: timeout set to 5 seconds
Jul 27 19:18:29 wirenboard-AUPZT7SN chat[18959]: abort on (ERROR)
Jul 27 19:18:29 wirenboard-AUPZT7SN chat[18959]: abort on (BUSY)
Jul 27 19:18:29 wirenboard-AUPZT7SN chat[18959]: send (AT^M)
Jul 27 19:18:29 wirenboard-AUPZT7SN chat[18959]: expect (OK)
Jul 27 19:18:34 wirenboard-AUPZT7SN chat[18959]: alarm
Jul 27 19:18:34 wirenboard-AUPZT7SN chat[18959]: Failed
Jul 27 19:19:20 wirenboard-AUPZT7SN chat[19374]: timeout set to 5 seconds
Jul 27 19:19:20 wirenboard-AUPZT7SN chat[19374]: abort on (ERROR)
Jul 27 19:19:20 wirenboard-AUPZT7SN chat[19374]: abort on (BUSY)
Jul 27 19:19:20 wirenboard-AUPZT7SN chat[19374]: send (AT^M)
Jul 27 19:19:21 wirenboard-AUPZT7SN chat[19374]: expect (OK)
Jul 27 19:19:26 wirenboard-AUPZT7SN chat[19374]: alarm
Jul 27 19:19:26 wirenboard-AUPZT7SN chat[19374]: Failed

(Через какое-то время модем всё-таки заработал)

Диагностическую информацию прислать не могу, так как:

Возможно, это из-за высокой нагрузки на CPU, см. моё описание ситуации Новая логика параметров опроса wb-mqtt-serial в wb-2204

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

Или это следствие неисправимой аппаратной ошибки контроллера ERRWB600010?

Ревизия: v6.8.1A
ветка testing, все пакеты актуальные на сегодняшний день.

Dmitry_Matsnev · 28.Июль.2022 07:32:13

пока не стартанул wb-mqtt-gpio, wb-mqtt-serial ругается, почему-то только на один, rs-485:

Дополнение: вскрытие показало, что этот модуль ревизии v.2.3D, остальные два модуля v.2.3C, и они стартуют нормально.

После остановки wb-rules удалось выгрузить диагностическую информацию:
diag_output_AUPZT7SN_2022-07-28-11.26.28.zip (130.5 КБ)

Буду крайне признателен за помощь.

BrainRoot · 28.Июль.2022 09:11:06

Добрый день.

В конфиге брокера параметр persistence включен? Если да - выключите.

Dmitry_Matsnev:

Jul 27 19:19:20 wirenboard-AUPZT7SN chat[19374]: timeout set to 5 seconds
Jul 27 19:19:20 wirenboard-AUPZT7SN chat[19374]: abort on (ERROR)
Jul 27 19:19:20 wirenboard-AUPZT7SN chat[19374]: abort on (BUSY)
Jul 27 19:19:20 wirenboard-AUPZT7SN chat[19374]: send (AT^M)
Jul 27 19:19:21 wirenboard-AUPZT7SN chat[19374]: expect (OK)
Jul 27 19:19:26 wirenboard-AUPZT7SN chat[19374]: alarm
Jul 27 19:19:26 wirenboard-AUPZT7SN chat[19374]: Failed

Но ведь логично - таймаут на 5 секунд, за 5 ничего не получено - все верно.

Dmitry_Matsnev · 28.Июль.2022 09:30:51

Выключен

Логично. Но это означает, что модем не работает?

Dmitry_Matsnev · 28.Июль.2022 09:35:20

Например, при последней перезагрузке wb-mqtt-gpio стартанул после седьмой попытки, через 12 минут после рестарта. Эту проблему как-то можно диагностировать?

BrainRoot · 28.Июль.2022 09:44:01

Означает что модем не ответил на at ответа может не быть по многим причинам: Выключен или недозагрузился, порт используется совместно с другим приложением, тем же wb-gsm.

смотрим в конфиг сервиса и видим что сначала запускается /usr/lib/wb-mqtt-gpio/generate-system-config.sh
Если выполнение скрипта заняло больше времени чем на него отведено - будет таймаут. А какая нагрузка на CPU?

Dmitry_Matsnev · 28.Июль.2022 09:49:06

почти всегда 100%

Я об этом писал в другой ветке

Dmitry_Matsnev · 28.Июль.2022 09:54:10

Опытным путем установлено, что пока не взлетит wb-mqtt-gpio, модем тоже не отвечает. Поэтому остается пока два вопроса:

Почему так мучительно стартует wb-mqtt-gpio
Почему иногда при перезагрузке виснет на 30 минут и более

BrainRoot · 28.Июль.2022 09:57:03

А чем занято?

Dmitry_Matsnev · 28.Июль.2022 10:01:50

wb-mqtt-serial и wb-rules, в меньшей степени - wb-mqtt-db и mosquitto
см. Новая логика параметров опроса wb-mqtt-serial в wb-2204 - #34 от пользователя Dmitry_Matsnev

Dmitry_Matsnev · 28.Июль.2022 10:28:05

Беру свои слова обратно. Несколько раз модем взлетал раньше wb-mqtt-gpio

Dmitry_Matsnev · 28.Июль.2022 10:54:02

При очередной перезагрузке wb-mqtt-gpio стартовал только на 29-й минуте

Всё это время загрузка CPU:

BrainRoot · 28.Июль.2022 12:30:46

Установите опрос serial с меньшими приоритетами, при загруженном CPU довольно характерные симптомы. А сколько всего топиков сейчас в системе?

Dmitry_Matsnev · 28.Июль.2022 13:39:47

Я не нашел способов посчитать кол-во топиков. Подскажите, как это можно сделать?

Приоритеты не заданы (а разве есть способ устанавливать приоритеты?), для самых часто меняющихся топиков установлен период опроса 5 сек.

BrainRoot · 28.Июль.2022 14:44:16

Да примерно, 100-500-1000

да, вот тут: https://github.com/wirenboard/wb-mqtt-serial#общая-информация
Ну и - для проверки отключите запуск wb-mqtt-serial и перезапустите контроллер.

Dmitry_Matsnev · 28.Июль.2022 15:35:17

В Settings->MQTT Channels 440 строчек. Возможно, это и есть общее кол-во топиков.

Если под приоритетами вы имеете ввиду read_period_ms, то я их устанавливал в 5 секунд для часто меняющихся топиков (типа температуры). Без этого опрос чаще и нагрузка еще больше, я об этом писал по ссылке выше. Вы изменили логику шедулера и теперь не существует способов ограничить частоту опроса топиков. Даже read_rate_limit_ms на порт или устройство не сильно спасает. А выставлять его в десятки секунд - это лишиться интерактивного управления (которое перестает быть интерактивным после задержки в 250 мс)

Dmitry_Matsnev · 02.Август.2022 15:02:15

Проблема устранена путем перехода на WB7

system · 09.Август.2022 15:03:06

Эта тема была автоматически закрыта через 7 дней после последнего ответа. В ней больше нельзя отвечать.