Сообщения log из wb-rules не попадают в лог

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

Перестали попадать сообщения из wb-rules в лог. Речь не только об отладочных сообщениях но даже о log.info.
В консоль браузера выходят, в syslog пусто.
Из каких либо значимых изменений установка node-red + перенос логов на отдельную карту памяти.

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

При рестарте wb-rules в логах:

22-02-2023 11:26:26.515	INFO: all rule files are loaded
22-02-2023 11:26:26.490	INFO: /usr/share/wb-rules/load_alarms.js is NOT under source root /etc/wb-rules
22-02-2023 11:26:26.373	ERROR: failed to SetValue for unexisting control wb-msw-v3_145/Buzzer: false
22-02-2023 11:26:26.220	INFO: /usr/share/wb-rules-system/rules/wbmz-battery.js is NOT under source root /etc/wb-rules
22-02-2023 11:26:26.193	INFO: system/DTS Version: failed to convert value '', passing raw
22-02-2023 11:26:26.138	sh: 4: /etc/wb_env.sh: source: not found
22-02-2023 11:26:26.054	INFO: /usr/share/wb-rules-system/rules/wb-mqtt-dac.js is NOT under source root /etc/wb-rules
22-02-2023 11:26:25.871	INFO: /usr/share/wb-rules-system/rules/system.js is NOT under source root /etc/wb-rules
22-02-2023 11:26:25.636	INFO: /usr/share/wb-rules-system/rules/power_status.js is NOT under source root /etc/wb-rules
22-02-2023 11:26:25.633	INFO: network/Ethernet 2 IP: failed to convert value '', passing raw
22-02-2023 11:26:25.622	INFO: knx/data: failed to convert value '', passing raw
22-02-2023 11:26:25.612	INFO: knx/data: failed to convert value '', passing raw
22-02-2023 11:26:25.571	INFO: knx/data: failed to convert value '', passing raw
22-02-2023 11:26:25.553	INFO: knx/data: failed to convert value '', passing raw
22-02-2023 11:26:25.548	INFO: network/Wi-Fi 2 IP: failed to convert value '', passing raw
22-02-2023 11:26:25.527	INFO: network/Wi-Fi IP: failed to convert value '', passing raw
22-02-2023 11:26:25.502	INFO: network/GPRS IP: failed to convert value '', passing raw
22-02-2023 11:26:25.393	Device "ppp0" does not exist.
22-02-2023 11:26:25.291	INFO: /usr/share/wb-rules-system/rules/power-class-battery.js is NOT under source root /etc/wb-rules
22-02-2023 11:26:25.133	INFO: /usr/share/wb-rules-system/rules/network.js is NOT under source root /etc/wb-rules
22-02-2023 11:26:24.998	INFO: /usr/share/wb-rules-system/rules/hwmon.js is NOT under source root /etc/wb-rules
22-02-2023 11:26:24.843	INFO: /usr/share/wb-rules-system/rules/buzzer.js is NOT under source root /etc/wb-rules
22-02-2023 11:26:24.815	INFO: [engine] Starting sync loop
22-02-2023 11:26:24.812	INFO: the engine is ready
22-02-2023 11:26:24.810	INFO: [engine] Starting main loop
22-02-2023 11:26:24.481	INFO: [wbgo_mqtt] wb-rules-engine-wirenboard-ARSDWYPR-3047: MQTT connection established
22-02-2023 11:26:24.446	INFO: [rule info] using file /var/lib/wirenboard/wbrules-persistent.db for persistent DB
22-02-2023 11:26:24.390	INFO: driver is ready
22-02-2023 11:26:24.252	INFO: wait for driver to become ready
22-02-2023 11:26:24.246	INFO: driver loop is started
22-02-2023 11:26:24.229	INFO: [wbgo_mqtt] rules-wirenboard-ARSDWYPR-3047: MQTT connection established
22-02-2023 11:26:24.206	INFO: driver is created
22-02-2023 11:25:35.969	INFO: [engine] Stopping sync loop

Система:

Welcome to Wiren Board 7.3.4 (s/n ARSDWYPR), release wb-2207 (as stable)
Linux wirenboard-ARSDWYPR 5.10.35-wb120+wb101 #2 SMP Tue Nov 22 12:49:35 UTC 2022 armv7l GNU/Linux

Прошу не удивляться что нет ошибок связанных с dac, закомментил файл.

2

Добрый день. А устройство wb-msw-v3_145 подключено? Работает?

3

Подключено.
Это из-за этой строчки:

biper_last_value = dev["wb-msw-v3_145"]["Buzzer"] = false;

За рамками defineRules. Переделаю само собой.

4

Для диагностики проблемы пришлите, пожалуйста, архив с диагностической информацией контроллера. Создание архива описано в документации.
Какой вывод systemctl status wb-rules?
Перенос логов выполнен корректно?

5 
systemctl status wb-rules
● wb-rules.service - MQTT Rule engine for Wiren Board
   Loaded: loaded (/lib/systemd/system/wb-rules.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2023-02-22 11:26:23 MSK; 6h ago
 Main PID: 3047 (wb-rules)
   CGroup: /system.slice/wb-rules.service
           └─3047 /usr/bin/wb-rules -syslog -editdir /etc/wb-rules/ /usr/share/wb-rules-system/rules/ /etc/wb-rules/ /usr/share/wb-rules/

diag_output_ARSDWYPR_2023-02-22-18.32.32.zip (95.0 КБ)

Касательно корректности переноса лога не знаю что там можно сделать не так. Логи других модулей пишутся. Проблема исключительно с сообщениями которые я пишу при помощи log из своих правил. Причем вначале одно или два попадает а последующие только в консоль браузера.

6

Небольшой апдейт.
Добавил обертку над штатным логированием:

...
clog_.debug = function (message, values) {
    var prepared = this.prepare(message, arguments);
    log.debug.apply(this, arguments);
    this.write('DEBUG', prepared);
};
clog_.info = function (message, values) {
    var prepared = this.prepare(message, arguments);
    log.info.apply(this, arguments);
    this.write('INFO', prepared);
};
...

В логах:

Mar  1 14:43:04 wirenboard-ARSDWYPR wb-rules[1585]: INFO: [rule info] virtual_bedroom_temperature changed target temperature 2570
Mar  1 14:43:04 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature got update for controller newValue 25.7, devName virtual_bedroom_temperature, cellName target_temp
Mar  1 14:43:04 wirenboard-ARSDWYPR root: INFO: mylogs virtual_bedroom_temperature changed target temperature 2570
Mar  1 14:43:05 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature t 2572 -> ft 2572, this.lastStateTime false, this.lastUsedTemp false
Mar  1 14:43:05 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature diff 2 currentF 12
Mar  1 14:43:05 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature push next log entry {time:1677670985002,state:0,target:2570,temp:2572,F:12}
Mar  1 14:43:05 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature update coefficient
Mar  1 14:44:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature t 2570 -> ft 2570.3233642578125, this.lastStateTime false, this.lastUsedTemp false
Mar  1 14:44:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature update coefficient
Mar  1 14:44:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature diff 0.3233642578125 currentF 12
Mar  1 14:44:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature can't find significant change of temperature. retain current state
Mar  1 14:44:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature push next log entry {time:1677671055002,state:0,target:2570,temp:2570.3233642578125,F:12}
Mar  1 14:45:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature t 2570 -> ft 2569.6041827499866, this.lastStateTime false, this.lastUsedTemp false
Mar  1 14:45:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature diff -0.39581725001335144 currentF 12
Mar  1 14:45:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature update coefficient
Mar  1 14:45:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature fix 2
Mar  1 14:45:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature push next log entry {time:1677671115002,state:0,target:2570,temp:2569.6041827499866,F:12}
Mar  1 14:45:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature start_temp 2572 start_time 14:43:05  diff_in_time -2.3958172500133514 time_coefficient 3.2302722658052607
Mar  1 14:46:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature t 2569 -> ft 2569.689806939634, this.lastStateTime false, this.lastUsedTemp false
Mar  1 14:46:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature update coefficient
Mar  1 14:46:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature diff -0.3101930603661458 currentF 12
Mar  1 14:46:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature fix 2
Mar  1 14:46:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature start_temp 2572 start_time 14:43:05  diff_in_time -2.310193060366146 time_coefficient 2.2103169173446724
Mar  1 14:46:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature push next log entry {time:1677671175002,state:0,target:2570,temp:2569.689806939634,F:12}
Mar  1 14:47:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature t 2569 -> ft 2569.289763002684, this.lastStateTime false, this.lastUsedTemp false
Mar  1 14:47:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature update coefficient
Mar  1 14:47:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature diff -0.7102369973158602 currentF 12
Mar  1 14:47:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature push next log entry {time:1677671235002,state:0,target:2570,temp:2569.289763002684,F:12}
Mar  1 14:47:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature fix 2
Mar  1 14:47:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature start_temp 2572 start_time 14:43:05  diff_in_time -2.71023699731586 time_coefficient 1.6797581148314642
Mar  1 14:48:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature update coefficient
Mar  1 14:48:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature t 2569 -> ft 2569.778134089101, this.lastStateTime false, this.lastUsedTemp false
Mar  1 14:48:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature diff -0.22186591089894137 currentF 12
Mar  1 14:48:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature start_temp 2572 start_time 14:43:05  diff_in_time -2.2218659108989414 time_coefficient 1.354751306367331
Mar  1 14:48:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature fix 2
Mar  1 14:48:15 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature push next log entry {time:1677671295002,state:0,target:2570,temp:2569.778134089101,F:12}
Mar  1 14:49:18 wirenboard-ARSDWYPR wb-rules[1585]: INFO: [rule info] virtual_bedroom_temperature changed target temperature 2560
Mar  1 14:49:18 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature got update for controller newValue 25.6, devName virtual_bedroom_temperature, cellName target_temp
Mar  1 14:49:18 wirenboard-ARSDWYPR root: INFO: mylogs virtual_bedroom_temperature changed target temperature 2560
Mar  1 14:49:25 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature t 2568 -> ft 2568, this.lastStateTime false, this.lastUsedTemp false
Mar  1 14:49:25 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature update coefficient
Mar  1 14:49:25 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature push next log entry {time:1677671365002,state:0,target:2560,temp:2568,F:12}
Mar  1 14:49:25 wirenboard-ARSDWYPR root: DEBUG: mylogs virtual_bedroom_temperature diff 8 currentF 12

Наталкивает на мысль что проблема именно с отладочными сообщениями, поскольку информационные проскакивают. Флаг отладки стоит само собой. Пробовал ставить снимать - не оказывает влияния. На странице топиков значения флага соответственно меняются.

7

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

9