Espeasy: Problem with Publish after TaskValueSet

[makonrus]

If you self compile, please state this and PLEASE try to ONLY REPORT ISSUES WITH OFFICIAL BUILDS!

Summarize of the problem/feature request

Simple rule:

on Sensor4#State do // Sensor1-Sensor4 is a optical sensors with 1-0 logik.
TaskValueSet 5,1,[Sensor1#State]+[Sensor2#State]+[Sensor3#State]+[Sensor4#State] //Writing to //Dummy device ("MessageSize" task #5) the sum of states of all sensors
TaskRun,5
Publish /%sysname%/MessageSize/Size,[MessageSize#Size] //Sending result to MQTT broker
endon

if Sensor1#State = 1 and Sensor2-Sensor4 states = 0 then the sum of states = 1 and the MessageSize#Size must be equal 1
And the MQTT broker should get the value 1.
But the broker gets the value 0.

Forum topic

Expected behavior

MQTT broker should receive value 1 in a /Entrance/MessageSize/Size topic

Actual behavior

MQTT broker gets the value 0 in a /Entrance/MessageSize/Size topic

Steps to reproduce

1. Add an optical binary sensor to the system. No need to add all 4 sensors
2. Add the above rule
3. Activate the sensor

System configuration

Hardware:
NODE MCU v3


ESP Easy version:

Build | 20102 - Mega
Libraries | ESP82xx Core 00000000, NONOS SDK 2.2.1(cfd48f3), LWIP: 2.0.3
GIT version | mega-20180815
Plugins | 48 [Normal]
Build Md5 | 51275887b0131357f4476b3dd8246191
Md5 check | passed.
Build time | Aug 15 2018 02:15:39
Binary filename | ESP_Easy_mega-20180815_normal_ESP8266_4096.bin

ESP Easy settings/screenshots:

Rules or log data

on Sensor1#State do
TaskValueSet 5,1,[Sensor1#State]+[Sensor2#State]+[Sensor3#State]+[Sensor4#State]
TaskRun,5
Publish /%sysname%/MessageSize/Size,[MessageSize#Size]
endon

### Log level INFO:
SW : Switch state 0 Output value 1
142801: EVENT: Sensor1#State=1.00
142833: ACT : TaskValueSet 5,1,1+0+0+0
142847: ACT : TaskRun,5
142875: **ACT : Publish /Entrance/MessageSize/Size,0**
142954: Command: taskvalueset
142956: Command: taskrun
142960: Dummy: value 1: 1.00
142960: Dummy: value 2: 0.00
142961: Dummy: value 3: 0.00
142961: Dummy: value 4: 0.00
142963: EVENT: MessageSize#Size=1.00
143013: ACT : gpio,2,0
143016: SW : GPIO 2 Set to 0
143021: EVENT: MessageSize#=0.00
143048: EVENT: MessageSize#=0.00
143074: EVENT: MessageSize#=0.00
143141: Command: publish

### Log level DEBUG More:
221499: EVENT: MessageSize#Size=1.00
221537: [if 1=0]=false
221540: else = true
221542: ACT : gpio,2,0
221544: SW : GPIO 2 Set to 0
221548: EVENT: MessageSize#Size=1.00 Processing time:49 milliSeconds
221549: EVENT: MessageSize#=0.00
221575: EVENT: MessageSize#=0.00 Processing time:26 milliSeconds
221576: EVENT: MessageSize#=0.00
221604: EVENT: MessageSize#=0.00 Processing time:28 milliSeconds
221605: EVENT: MessageSize#=0.00
221631: EVENT: MessageSize#=0.00 Processing time:26 milliSeconds
221656: **MQTT : /Entrance/MessageSize/Size 1**
221672: Command: publish

[TD-er]

Could you please also test this test build I made here: https://github.com/letscontrolit/ESPEasy/pull/1669#issuecomment-418520967
You can read the whole thread over there, but the TL;DR version is:
All messages sent by controllers will be queued and sent at a pace the receiving end can keep up with.

[makonrus]

I installed the ESP_Easy_v2.0.0-dev11-1626-ge6105bf_normal_ESP8266_4096 firmware
Nothing to changed with my issue.

INFO:
476321: SW : Switch state 0 Output value 1
476324: EVENT: Sensor1#State=1.00
476357: ACT : TaskValueSet 5,1,1+0+0+0
476389: ACT : Publish /Entrance/MessageSize/Size,0
476437: Command: taskvalueset
476438: Command: publish

DEBUG MORE:
526222: SW : Switch state 0 Output value 1
526225: EVENT: Sensor1#State=1.00
526259: ACT : TaskValueSet 5,1,1+0+0+0
526288: ACT : Publish /Entrance/MessageSize/Size,0
526322: EVENT: Sensor1#State=1.00 Processing time:97 milliSeconds
526339: Command: taskvalueset
526341: Command: publish

[TD-er]

I wonder if the values are even gathered.

TaskValueSet 5,1,[Sensor1#State]+[Sensor2#State]+[Sensor3#State]+[Sensor4#State]

Maybe TaskValueSet 5,1,1+0+0+0 will work, but I have to look more closely to see in the code where it should translate [Sensor1#State] into "1".

This rules part of the code really should get some attention.

[giig1967g]

I can confirm the bug.
It seems that the new value set in the rule is not updated until the rule finishes.
So any reference to that task/value will always return the old value and not the new value.

Example:
(assume device1#task1 = 0):

on testRule do
  Publish /%sysname%/taskvalue,[device1#task1]
  taskvalueset,1,1,1
  Publish /%sysname%/taskvalue,[device1#task1]
endon

The published values are both 0.
This behaviuor happens with other commands too.

I suspect that the reason could be in the command scheduling function _schedule_command_timer()_

[TD-er]

Hmm, if that's true, then we need some parameter to run commands that will execute immediately.
Or add some return option in the rules handling to process the rules line by line and continue after running other time critical tasks.

[giig1967g]

I haven't checked deeply yet, but my suspect is that when the command is scheduled, the parameters are evaluated. So if the execution of the taskvalueset command happens AFTER the schedule of the publish command, we see this behaviour.
I saw this happening when I was writing the code for the #1731 .
In the log (debug) you can see what happens:
ALL ACTIONS are scheduled with current parameters, the all COMMANDS are executed.

Another idea could be a new command like "FLUSH" that will executre the pending commands in the queue and then will continue execution.

[TD-er]

Maybe we can simply do a few calls to the scheduler inbetween rules processing.
But then the commands from rules should not be handled by the scheduler.

The main problem is that the rules execution may take a lot of time, that's why I added the command handling to the scheduler.

[wolverinevn]

This issue of update TaskValue create many troubles to me while writing code. To by pass, I need to seperate the rules to some event.
Ex:
on event1 do
taskvalueset,1,1,1+2+3
taskrun,5
if [test#1]>5 //test=task1
....

Must be changed to>>>
on event1 do
taskvalueset,1,1,1+2+3
event,check1
endon
on check1 do
if [test#1]>5
...

[Grovkillen]

@wolverinevn Yes this is common practice when it comes to the rules engine.

[TD-er]

You mean adjusting a value and reading from it cannot be done in the same on...do...endon scope?
That's a known issue at this moment.
And it most likely has to do with the commands still being handled by the scheduler.

I still have to remove that from the scheduler, but it is not clear to me why that results in reboots when I do.

[uzi18]

@giig1967g
what is on Serial info log if You use this rule:

on testRule do
  taskvalueset,1,1,0
  taskvalueset,1,1
  Publish /%sysname%/taskvalue,[device1#task1]
  taskvalueset,1,1,1
  taskvalueset,1,1
  Publish /%sysname%/taskvalue,[device1#task1]
endon

[giig1967g]

It's a known bug.

See my log.
(initial value of task1#value1=10)

1673381: EVENT: testrule
1673493: ACT : taskvalueset,1,1,0
1673506: ACT : taskvalueset,1,1
1673532: ACT : Publish /ESP22/taskvalue,10
1673545: ACT : taskvalueset,1,1,1
1673558: ACT : taskvalueset,1,1
1673584: ACT : Publish /ESP22/taskvalue,10
1673634: EVENT: Clock#Time=Tue,19:48
1673797: Command: taskvalueset
1673800: Command: taskvalueset
1673802: Command: publish
1673803: Command: taskvalueset
1673805: Command: taskvalueset
1673806: Command: publish

[TD-er]

Is this one now fixed?
Please test with latest build, which will be made tonight. (20181128)

[Grovkillen]

Closing this now. Open if still an issue.