Перестают работать wb-rules с ошибкой [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken

[Jenya]

Приветствую, контроллер wb7

Подключено около 55 сериал устройств на 3х линиях и один датчик зигби. Падают правила с ошибкой подключения к брокеру (ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0x1984c40 } 50940}) ) при: сохранении/изменении больших файлов правил, перезагрузке контроллера, перезагрузке mosquitto, перезагрузке wb-rules. Возможно они падают и от других действий, но эти мне удалось выявить наверняка. Ошибка проявилась недавно при изменении правила и до этого не возникала, контроллер несколько месяцев работал стабильно с текущими правилами, которые не сильно изменялись.
Метод восстановления нормальной работы, на данный момент, выглядит так: остановка wb-mqtt-serial → рестарт wb-rules (занимает несколько минут) → запуск wb-mqtt-serial. После этих действий контроллер работает без ошибок.
Сбрасывал контроллер к заводским настройкам, но безрезультатно. Прикладываю диагностический архив, текст и скрины логов.

log_20250301T143159.log (158,5 КБ)
diag_AA6QMN3S_2025-03-02-02.32.34.zip (341,6 КБ)

[BrainRoot]

Добрый день.
Процесс wb-rules занимает довольно много ресурсов:

root     23914 54.4  1.9 898736 39428 ?        Ssl  Mar01 396:11 /usr/bin/wb-rules -syslog -editdir /etc/wb-rules/ /usr/share/wb-rules-system/rules/ /etc/wb-rules/ /usr/share/wb-rules/

Причем как по процессору так и по памяти.
Точно ли в нем нет рекурсивного создания правил? Очень похоже по симптомам.

[Jenya]

Здравствуйте, проверил все, рекурсивного создания правил нет (могу приложить архив с правилами, если требуется), но самих правил создается достаточно много, возможно проблема в количестве? Еще смущает, что проблема проявилась только недавно после обновления, раньше ее не было

[BrainRoot]

Добрый день.
Подобные ошибки (переполнение очереди) получается, обычно эмулировать так:

//03_10_test_01.js
function makeNewRule(aa, bb){
  defineRule("RuleFor"+aa, {
  whenChanged: aa,
    then: function(value) {
      dev[bb] = value;
      log.info("makeNewRule");
      makeNewRule(aa, bb)
    }
})
};

makeNewRule("power_status/Vin", "buzzer/frequency");

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

[Evgenij_Kiselev]

Добрый день! Наблюдаю аналогичную проблему у себя: правила работали (и работают) без сбоев, в Журнале критичных ошибок не было. Изменения вношу периодически, но 90% правил не меняются уже больше года.
Сегодня поставил обновления, после этого решил внести изменения в одно из правил. Изменения не сохранятся, в Журнале появились критические ошибки, связанные с MQTT.
По моим наблюдениям:

• если менять небольшие правила (до 100 строк) - изменения сохраняются
• если менять правила 100+ строк - процесс сохранения зависает и в Журнале начинают появляться ошибки (см. скрин)
• спустя небольшое время после пары-тройки таких попыток сохранить изменения в правилах контроллер сам перезагружается
• попробовал удалить все правила и возвращать их частями (включая самые древние, которые не менялись год точно) - отсеять “кривое” правило не удалось, т.к. вернул половину - все работает, попытался сохранить любое большое - ошибки, маленькое - сохранилось. Также и с другой половиной правил
• отдельно подчеркну, что во время проверок пробовал “менять” правила по принципу - добавил/удалил пустую строку между функциями - и все равно это приводило к бесконечному процессу сохранения + появлению критических ошибок в журнале

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

UPD: спустя 4 часа после публикации данного поста и прекращения попыток сохранять изменения в правилах посмотрел Журнал - ни единой критической ошибки, все штатно, как и было до обнаружения проблемы. А в то время, когда тестировал и пытался сохранять правила - ошибки сыпались обильно. Такое ощущение, что именно сохранение правил на 100+ строк что-то подвешивает так, что mqtt начинает сбоить

[Jenya]

Да, симптомы аналогичные, уже словил такое же поведение и на другом контроллере, когда количество модбас устройств выросло с 20 до 35. С большими правилами такие проблемы возникают почти со 100% вероятностью, с малыми действительно все хорошо, но иногда баг ловится даже при сохранении небольших файлов правил. Хорошо, что я не один…

[Jenya]

Так же хочу добавить, что баг ловится на контроллерах с большим количеством подключенных модбас устройств (40+ штук), хватает даже одного файла правил в котором создаются более 30 маленьких правил и 5-10 виртуальных устройств, тестировал на другом “свежем” контроллере пока была возможность. Пример правила прикладываю, если поддержка хочет протестировать, то рекомендую использовать для этого инсталляции с большим количеством модбас устройств, видимо их опрос как то влияет на то что брокер падает
AutoWatering.js (17,2 КБ)

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

На контроллерах с большим количеством модбас устройств при отключении драйвера wb-serial, правила получается сохранять и редактировать без возникновения каких либо ошибок (в последнее время только так и приходится работать с правилами контроллера - останавливая опрос устройств). После сохранения правил, запускаю опрос и все работает без ошибок.

[Jenya]

Сегодня словил ошибку на контроллере с большим количеством зигби устройств и с двумя модбас устройствами (писал ранее, рано радовался) при изменении большого правила. Второе модбас устройство добавил на прошлой неделе, это датчик wb-msw, ранее подобных проблем на данном контроллере не наблюдалось. Вылечилось привычным способом через отключение драйвера wb-mqtt-serial и перезагрузкой wb-rules. Скоро будет возможность протестировать свежий контроллер дома, отпишусь о результатах

[Dmitry_Matsnev]

Я наблюдаю такие же симптомы. Например, последняя попытка сохранения правила:

Apr 07 12:35:52 wirenboard wb-rules[22159]: INFO: reloading file: /etc/wb-rules/10_temperature_sensors.js
Apr 07 12:36:03 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0xed8cc0 <nil>} 9258})
Apr 07 12:36:13 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0xed9240 <nil>} 9260})
Apr 07 12:36:23 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0xed9440 <nil>} 9261})
Apr 07 12:36:26 wirenboard mosquitto[21545]: 1744018586: Client wb-rules-engine-wirenboard-22159 closed its connection.

После этого приходится делать service wb-rules restart

[BrainRoot]

Какая нагрузка на CPU в это время?
Иными словами - нужен способ воспроизвести подобное. Потому что (пока) не получилось.

[Dmitry_Matsnev]

Не сильно загружен

[Dmitry_Matsnev]

Воспроизвести удается не всегда. Иногда при сохранении правила падает, иногда с тем же самым правилом не падает и нормально его обновляет, никакой системы.

Направляю еще немного логов, может как-то прояснит ситуацию:

Apr 07 12:35:52 wirenboard wb-rules[22159]: INFO: reloading file: /etc/wb-rules/10_temperature_sensors.js
Apr 07 12:36:03 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0xed8cc0 <nil>} 9258})
Apr 07 12:36:13 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0xed9240 <nil>} 9260})
Apr 07 12:36:23 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0xed9440 <nil>} 9261})
Apr 07 12:36:26 wirenboard mosquitto[21545]: 1744018586: Client wb-rules-engine-wirenboard-22159 closed its connection.
Apr 07 12:36:33 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0xea9c40 <nil>} 9262})
Apr 07 12:36:39 wirenboard mosquitto[21545]: 1744018599: Client rules-wirenboard-22159 disconnected: Broken pipe.
Apr 07 12:36:40 wirenboard systemd[1]: Stopping MQTT Rule engine for Wiren Board...
Apr 07 12:36:43 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0xed9880 <nil>} 9263})
Apr 07 12:36:53 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0x138c2c0 <nil>} 9264})
Apr 07 12:37:03 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0x138c640 <nil>} 9265})
Apr 07 12:37:13 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0x138c7c0 <nil>} 9266})
Apr 07 12:37:23 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0x138c840 <nil>} 9267})
Apr 07 12:37:33 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0x138c9c0 <nil>} 9268})
Apr 07 12:37:43 wirenboard wb-rules[22159]: ERROR: [wbgo_mqtt] MQTT token wait timeout: *mqtt.PublishToken (&{{{{0 0} 0 0 {{} 0} {{} 0}} 0x138ca40 <nil>} 9269})
Apr 07 12:37:53 wirenboard wb-rules[22159]: panic: [engine] CallSync stuck!
Apr 07 12:37:53 wirenboard wb-rules[22159]: goroutine 69 [running]:
Apr 07 12:37:53 wirenboard wb-rules[22159]: github.com/wirenboard/wb-rules/wbrules.(*RuleEngine).CallSync(0xc02e00, 0x10b5d88)
Apr 07 12:37:53 wirenboard wb-rules[22159]:         github.com/wirenboard/wb-rules/wbrules/engine.go:978 +0x144
Apr 07 12:37:53 wirenboard wb-rules[22159]: github.com/wirenboard/wb-rules/wbrules.(*RuleEngine).DefineMqttTracker.(*RuleEngine).newTrackHandler.func2({{0xe4c060, 0x16}, {0xc68840, 0x36}, 0x0, 0x0})
Apr 07 12:37:53 wirenboard wb-rules[22159]:         github.com/wirenboard/wb-rules/wbrules/engine.go:1950 +0xec
Apr 07 12:37:53 wirenboard wb-rules[22159]: github.com/wirenboard/wbgo-private.(*PahoMQTTClient).subscribe.func1({0xaab75320, 0xcbc180}, {0xaab750bc, 0x150e930})
Apr 07 12:37:53 wirenboard wb-rules[22159]:         github.com/wirenboard/wbgo-private/mqtt.go:321 +0x370
Apr 07 12:37:53 wirenboard wb-rules[22159]: github.com/eclipse/paho%2emqtt%2egolang.(*router).matchAndDispatch.func2()
Apr 07 12:37:53 wirenboard wb-rules[22159]:         github.com/eclipse/paho.mqtt.golang@v1.5.0/router.go:218 +0xa14
Apr 07 12:37:53 wirenboard wb-rules[22159]: created by github.com/eclipse/paho%2emqtt%2egolang.(*router).matchAndDispatch in goroutine 67
Apr 07 12:37:53 wirenboard wb-rules[22159]:         github.com/eclipse/paho.mqtt.golang@v1.5.0/router.go:173 +0x2a4
Apr 07 12:37:53 wirenboard systemd[1]: wb-rules.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Apr 07 12:37:53 wirenboard systemd[1]: wb-rules.service: Failed with result 'exit-code'.
Apr 07 12:37:53 wirenboard systemd[1]: Stopped MQTT Rule engine for Wiren Board.
Apr 07 12:37:53 wirenboard systemd[1]: wb-rules.service: Consumed 1min 48.658s CPU time.
Apr 07 12:37:53 wirenboard systemd[1]: Started MQTT Rule engine for Wiren Board.
Apr 07 12:37:53 wirenboard wb-rules[24591]: INFO: broker URL is default and mosquitto socket detected, trying to connect via it
Apr 07 12:37:53 wirenboard wb-rules[24591]: INFO: driver is created
Apr 07 12:37:53 wirenboard mosquitto[21545]: 1744018673: New connection from /var/run/mosquitto/mosquitto.sock:0 on port 0.
Apr 07 12:37:53 wirenboard mosquitto[21545]: 1744018673: New client connected from /var/run/mosquitto/mosquitto.sock:0 as rules-wirenboard-24591 (p2, c1, k30).
Apr 07 12:37:53 wirenboard wb-rules[24591]: INFO: [wbgo_mqtt] rules-wirenboard-24591: MQTT connection established
Apr 07 12:37:53 wirenboard wb-rules[24591]: INFO: driver loop is started
Apr 07 12:37:53 wirenboard wb-rules[24591]: INFO: wait for driver to become ready
Apr 07 12:37:55 wirenboard wb-rules[24591]: INFO: driver is ready
Apr 07 12:37:55 wirenboard wb-rules[24591]: INFO: [rule info] using file /var/lib/wirenboard/wbrules-persistent.db for persistent DB
Apr 07 12:37:55 wirenboard mosquitto[21545]: 1744018675: New connection from /var/run/mosquitto/mosquitto.sock:0 on port 0.
Apr 07 12:37:55 wirenboard mosquitto[21545]: 1744018675: New client connected from /var/run/mosquitto/mosquitto.sock:0 as wb-rules-engine-wirenboard-24591 (p2, c1, k30).
Apr 07 12:37:55 wirenboard wb-rules[24591]: INFO: [wbgo_mqtt] wb-rules-engine-wirenboard-24591: MQTT connection established
Apr 07 12:37:55 wirenboard wb-rules[24591]: INFO: [engine] Starting main loop
Apr 07 12:37:55 wirenboard wb-rules[24591]: INFO: the engine is ready
Apr 07 12:37:55 wirenboard wb-rules[24591]: INFO: [engine] Starting sync loop
Apr 07 12:37:56 wirenboard wb-rules[24591]: WARNING: [rule warning] resetResolverName для действия "whenChange" не установлен
Apr 07 12:37:56 wirenboard wb-rules[24591]: WARNING: [rule warning] DAC: no config file

Обратите внимание, что перезагрузка wb-rules занимает больше минуты

[Dmitry_Matsnev]

@Jenya

Так же хочу добавить, что баг ловится на контроллерах с большим количеством подключенных модбас устройств (40+ штук),

У меня 57 модбас устройств + zigbee. Всего 8228 топиков mqtt. Правил около двух десятков разной степени сложности.

[BrainRoot]

Для ттго чтобы собрать похожий стенд - потребуется несколько дней.