Перезагрузка wb-rules 1-2 раза в день из-за wbgo-private

Программное обеспечение Rule Engine
1

Доброго дня!
На контроллере wirenboard 7.3.4 5.10.35-wb175 release wb-2504 (as stable) 1 или 2 раза в день перезагружается движок правил wb-rules и mqtt брокер. Я не могу понять почему…

Вот логи контроллера:

21-06-2025 10:18:04.282 [wb-rules] github.com/eclipse/paho.mqtt.golang.(*router).matchAndDispatch.func2()
21-06-2025 10:18:04.282 [wb-rules] goroutine 6 [chan receive]:
21-06-2025 10:18:04.282 [wb-rules] github.com/eclipse/paho.mqtt.golang@v1.5.0/client.go:595 +0x388
21-06-2025 10:18:04.282 [wb-rules] created by github.com/eclipse/paho.mqtt.golang.(*client).startCommsWorkers in goroutine 4
21-06-2025 10:18:04.282 [wb-rules] github.com/eclipse/paho.mqtt.golang@v1.5.0/ping.go:48 +0x230
21-06-2025 10:18:04.282 [wb-rules] github.com/eclipse/paho.mqtt.golang.keepalive(0xc74000, {0xac3be008, 0xc220d8})
21-06-2025 10:18:04.282 [wb-rules] goroutine 5 [select]:
21-06-2025 10:18:04.282 [wb-rules] github.com/wirenboard/wbgo-private/mqtt.go:216 +0x17c
21-06-2025 10:18:04.282 [wb-rules] created by github.com/wirenboard/wbgo-private.(*PahoMQTTClient).Start in goroutine 1
21-06-2025 10:18:04.282 [wb-rules] github.com/wirenboard/wbgo-private/mqtt.go:218 +0x84
21-06-2025 10:18:04.282 [wb-rules] github.com/wirenboard/wbgo-private.(*PahoMQTTClient).Start.func1()
21-06-2025 10:18:04.282 [wb-rules] goroutine 16 [select]:
21-06-2025 10:18:04.282 [wb-rules] github.com/wirenboard/wbgo-private/driver_frontend.go:728 +0xf4
21-06-2025 10:18:04.282 [wb-rules] created by github.com/wirenboard/wbgo-private.(*driverBase).StartLoop in goroutine 1
21-06-2025 10:18:04.274 [wb-rules] github.com/wirenboard/wbgo-private/driver_frontend.go:732 +0xb0
21-06-2025 10:18:04.274 [wb-rules] github.com/wirenboard/wbgo-private.(*driverBase).StartLoop.func1()
21-06-2025 10:18:04.274 [wb-rules] github.com/wirenboard/wbgo-private/driver_frontend.go:692 +0x11c
21-06-2025 10:18:04.274 [wb-rules] github.com/wirenboard/wbgo-private.(*driverBase).LoopOnce(0xc64120, 0x0)
21-06-2025 10:18:04.274 [wb-rules] goroutine 3 [select]:
21-06-2025 10:18:04.274 [wb-rules] os/signal/signal.go:151 +0x28
21-06-2025 10:18:04.274 [wb-rules] created by os/signal.Notify.func1.1 in goroutine 1
21-06-2025 10:18:04.274 [wb-rules] os/signal/signal_unix.go:23 +0x14
21-06-2025 10:18:04.274 [wb-rules] os/signal.loop()
21-06-2025 10:18:04.274 [wb-rules] runtime/sigqueue.go:152 +0x34
21-06-2025 10:18:04.274 [wb-rules] os/signal.signal_recv()
21-06-2025 10:18:04.274 [wb-rules] goroutine 22 [syscall, 420 minutes]:
21-06-2025 10:18:04.274 [wb-rules] github.com/wirenboard/wb-rules/main.go:205 +0x17e8
21-06-2025 10:18:04.274 [wb-rules] main.main()
21-06-2025 10:18:04.274 [wb-rules] goroutine 1 [chan receive, 420 minutes]:
21-06-2025 10:18:04.274 [wb-rules] github.com/eclipse/paho.mqtt.golang@v1.5.0/router.go:173 +0x2a4
21-06-2025 10:18:04.274 [wb-rules] created by github.com/eclipse/paho.mqtt.golang.(*router).matchAndDispatch in goroutine 25
21-06-2025 10:18:04.274 [wb-rules] github.com/eclipse/paho.mqtt.golang@v1.5.0/router.go:218 +0xa14
21-06-2025 10:18:04.274 [wb-rules] github.com/eclipse/paho.mqtt.golang.(*router).matchAndDispatch.func2()
21-06-2025 10:18:04.274 [wb-rules] github.com/wirenboard/wbgo-private/mqtt.go:321 +0x370
21-06-2025 10:18:04.274 [wb-rules] github.com/wirenboard/wbgo-private.(*PahoMQTTClient).subscribe.func1({0xab574328, 0xc74180}, {0xab5740c4, 0x1344480})
21-06-2025 10:18:04.273 [wb-rules] github.com/wirenboard/wb-rules/wbrules/engine.go:1944 +0xc8
21-06-2025 10:18:04.273 [wb-rules] github.com/wirenboard/wb-rules/wbrules.(*RuleEngine).DefineMqttTracker.(*RuleEngine).newTrackHandler.func2({{0x1148b20, 0x1f}, {0xf21240, 0x5}, 0x0, 0x1})
21-06-2025 10:18:04.271 [wb-rules] goroutine 27 [running]:
21-06-2025 10:18:04.267 [wb-rules] fatal error: concurrent map iteration and map write
21-06-2025 10:18:03.279 RTL871X: set group key camid:1, addr:00:00:00:00:00:00, kid:1, type:TKIP

Скормил эти логи chat-gpt:

Причина перезагрузки wb-rules и MQTT брокера
В предоставленных логах контроллера Wiren Board отчетливо видна критическая ошибка:
fatal error: concurrent map iteration and map write
Это стандартная ошибка языка Go, означающая, что несколько горутин одновременно обращаются к одной и той же карте (map) для чтения и записи без синхронизации. В Go встроенные map не являются потокобезопасными, и при попытке одновременного чтения и записи возникает фатальная ошибка, которая завершает процесс.
В вашем случае wb-rules (движок правил) работает на Go и, судя по стеку вызовов, использует MQTT-клиент paho.mqtt.golang. Ошибка возникает внутри кастомного кода Wiren Board (wbgo-private, wbrules), который, вероятно, неправильно синхронизирует доступ к общей карте при обработке событий MQTT. После такой ошибки процесс wb-rules аварийно завершается, что может приводить и к перезапуску MQTT-брокера, если они связаны или настроены на совместный рестарт.
Почему это происходит 1-2 раза в день
• Скорее всего, ошибка проявляется при определённом стечении обстоятельств: когда одновременно срабатывают несколько правил или приходят сообщения по MQTT, которые обрабатываются параллельно.
• Если у вас много устройств или часто происходят события, вероятность столкновения горутин возрастает.
• Подобные ошибки могут быть спровоцированы некорректно написанными пользовательскими правилами, но чаще — багом в самой реализации wb-rules или используемых драйверах.

Как устранить
Для разработчиков ПО:
• Необходимо исправить код, чтобы доступ к map происходил с использованием синхронизации (например, через sync.RWMutex или sync.Map).
• Если используете сторонние модули или плагины, убедитесь, что они не нарушают потокобезопасность.
Для пользователя:
• Проверьте, не появлялись ли обновления прошивки или движка правил для вашей версии Wiren Board — подобные ошибки часто устраняются в новых релизах.
• Если есть возможность, временно отключите или упростите пользовательские правила, чтобы выявить, не связано ли падение с конкретным скриптом.
• Сообщите об ошибке в официальную поддержку Wiren Board, приложив логи — возможно, проблема уже известна.
Дополнительные замечания
• Аналогичные проблемы с периодическими сбоями и странным поведением устройств по MQTT обсуждаются и другими пользователями Wiren Board, что подтверждает наличие багов в реализации брокера или движка правил.
• Если MQTT-брокер и wb-rules перезапускаются одновременно, проверьте настройки Watchdog и зависимостей сервисов, чтобы исключить каскадные рестарты из-за одной ошибки.

Резюме
Ваши логи однозначно указывают на баг в многопоточном доступе к map в wb-rules. Это требует исправления на уровне исходного кода или обновления ПО. До выхода патча — минимизируйте количество параллельных событий и обратитесь в поддержку Wiren Board с логами для ускорения решения проблемы.

3

Здравствуйте. Пришлите, пожалуйста, также диагностический архив. Создание архива описано в документации.

4

приложен диагностический архив, доступен только сотрудникам поддержки
(355.4 KB)

8

Добрый день!

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

Можете, пожалуйста, уточнить, какое именно действие или событие отрабатывает перед сбоем?
Эта информация поможет воспроизвести проблему и передать её разработчикам для анализа и устранения.

9

А как это можно проверить? В логах непосредственно перед падением ничего привлекающего внимание нет:

…
24-06-2025 09:23:27.274 [wb-rules] github.com/eclipse/paho.mqtt.golang@v1.5.0/router.go:218 +0xa14
24-06-2025 09:23:27.274 [wb-rules] github.com/eclipse/paho.mqtt.golang.(*router).matchAndDispatch.func2()
24-06-2025 09:23:27.274 [wb-rules] github.com/wirenboard/wbgo-private/mqtt.go:321 +0x370
24-06-2025 09:23:27.274 [wb-rules] github.com/wirenboard/wbgo-private.(*PahoMQTTClient).subscribe.func1({0xab375328, 0xdb0180}, {0xab3750c4, 0xffc180})
24-06-2025 09:23:27.274 [wb-rules] github.com/wirenboard/wb-rules/wbrules/engine.go:1944 +0xc8
24-06-2025 09:23:27.274 [wb-rules] github.com/wirenboard/wb-rules/wbrules.(*RuleEngine).DefineMqttTracker.(*RuleEngine).newTrackHandler.func2({{0xcdd580, 0x1f}, {0x1087430, 0x4}, 0x0, 0x1})
24-06-2025 09:23:27.274 [wb-rules] goroutine 69 [running]:
24-06-2025 09:23:27.248 [wb-rules] fatal error: concurrent map iteration and map write
24-06-2025 09:20:35.960 [mosquitto] 1750746035: Client auto-9EEE472B-513C-2F85-3561-F42CEEB6348A disconnected.
24-06-2025 09:20:35.960 [mosquitto] 1750746035: New client connected from /var/run/mosquitto/mosquitto.sock:0 as auto-9EEE472B-513C-2F85-3561-F42CEEB6348A (p2, c1, k60).
24-06-2025 09:20:35.950 [mosquitto] 1750746035: New connection from /var/run/mosquitto/mosquitto.sock:0 on port 0.

Заметил интересную особенность, что падение происходит либо ночью, либо утром - в течение дня такое поведение не наблюдалось.

10

Есть ли какие-то сценарии, срабатывающие по крону?

13

да, погода обновляется каждые 10 минут:

defineRule("weather_call", {	
  when: cron("@every 10m"),
  then: function() {
    getWeather();
    startTimer("wait_weather", 5 * 1000);  		
    log("OM - 10 min update weather request");
  }
});
14

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

15

Один из топиков у меня действительно через trackMqtt проверялся из двух разных правил:

trackMqtt("Sprut.hub/accessories/320/13/15", function(Msg) {
//...

я не был в курсе, что так делать некорректно, попробую убрать в одном из правил и отслеживать только состояние вирт устройства

Еще обнаружил некоторое количество ошибок такого типа:

24-06-2025 18:25:53.533 [wb-rules]	ERROR: control virtual-zb-9/info SetValue() error: can't convert control value 'map[]' (type map[string]interface {}) to datatype '0'
24-06-2025 18:25:53.530 [wb-rules]	ERROR: control virtual-zb-9/state SetValue() error: can't convert control value 'map[]' (type map[string]interface {}) to datatype '0'

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

for i in {1..9}; do
  mosquitto_pub -r -t "/devices/virtual-zb-$i/meta" -n
  mosquitto_pub -r -t "/devices/virtual-zb-$i/controls/state" -n  
  mosquitto_pub -r -t "/devices/virtual-zb-$i/controls/state/meta" -n
  mosquitto_pub -r -t "/devices/virtual-zb-$i/controls/info" -n
  mosquitto_pub -r -t "/devices/virtual-zb-$i/controls/info/meta" -n
  mosquitto_pub -r -t "/devices/virtual-zb-$i/controls/enable" -n
  mosquitto_pub -r -t "/devices/virtual-zb-$i/controls/enable/meta" -n
  mosquitto_pub -r -t "/devices/virtual-zb-$i/controls/action" -n
  mosquitto_pub -r -t "/devices/virtual-zb-$i/controls/action/meta" -n
done

systemctl restart wb-rules

Может это в частности и приводит к

[wb-rules] fatal error: concurrent map iteration and map write

?

В любом случае, на текущий момент отключил правило с дублирующим trackMqtt - буду наблюдать и ждать очередного рестарта ) Как-то спровоцировать я это не могу (не знаю как).