Stack overflow at chained events in irrigation-control-rules

[Micha_he]

I've a problem with my rules of my irrigation control (beta/develop-state).

The event-rule 'VentilSchalten' (without the current comments) switch my valves on or off. The event-commands like 'Event,VentilSchalten=1,1' works as I expect.

The event-rule 'AutoPrgStartStop' should start the program 1-3 (Task 9 Value 1), with different segment-sequences (Task 9 Value 2). Tested, seems to work like I planned.

The event-rule 'AutoPrgWeiter' should switch to the next segment. Test looks good.

But If the event 'AutoPrgWeiter' trigger the event 'VentilSchalten' with the two needed parameters (e.g. VertilSchalten=1,1) and the event 'VentilSchalten' has all source code activated, the ESP reboot with a reason 'Software Watchdog'. But it work, If I comment all and do only a Let with the two eventvalues.

Can someone have a look to it ? Maybe a problem with the stack of the eventvalues ? In a simple test nested event-rules work at least to deep to three event-rules.

Here is the device-configuration:

Bewaesserung_Devices.jpg (72.81 KiB) Viewed 20106 times

rules1.txt:

Code: Select all

on System#Boot do
  PcfGpio,1,0  // Ventil1
  PcfGpio,2,0  // Ventil2
  PcfGpio,3,0  // Ventil3
  PcfGpio,4,0  // Ventil4
  PcfGpio,5,0  // Ventil5
  PcfGpio,6,0  // Ventil6
  Gpio,13,0    // Relais 12V Versorgung
  if [Zeiten1#Dauer1]=0
    TaskValueSet,7,1,15
  endif
  if [Zeiten1#Dauer2]=0
    TaskValueSet,7,2,10
  endif
  if [Zeiten1#Dauer3]=0
    TaskValueSet,7,3,15
  endif
  if [Zeiten1#Dauer4]=0
    TaskValueSet,7,4,10
  endif
  if [Zeiten2#Dauer5]=0
    TaskValueSet,8,1,10
  endif
  if [Zeiten2#Dauer6]=0
    TaskValueSet,8,2,8
  endif
  if [Zeiten2#Anpassung]=0
    TaskValueSet,8,3,1
  endif
endon

on MQTT#Connected do
  Event,Statusabfrage
endon

on Statusabfrage do
  Publish,/%sysname%/status/LWT,Connected
  Publish,/%sysname%/Ventil1/Status,[Ventil1#Status]
  Publish,/%sysname%/Ventil2/Status,[Ventil2#Status]
  Publish,/%sysname%/Ventil3/Status,[Ventil3#Status]
  Publish,/%sysname%/Ventil4/Status,[Ventil4#Status]
  Publish,/%sysname%/Ventil5/Status,[Ventil5#Status]
  Publish,/%sysname%/Ventil6/Status,[Ventil6#Status]
endon

ruels2.txt:

Code: Select all

on VentilSchalten do
  Let,%eventvalue1%,%eventvalue2%
  // Event,PumpeUndNT=%eventvalue2%
  PcfGpio,%eventvalue1%,%eventvalue2%
  // if %eventvalue1%>0 and %eventvalue1%<5
  //   Let,7,[Zeiten1#Dauer%eventvalue1%]*[Zeiten2#Anpassung]*60
  // endif
  // if %eventvalue1%>4 and %eventvalue1%<7
  //   Let,7,[Zeiten2#Dauer%eventvalue1%]*[Zeiten2#Anpassung]*60
  // endif
  // if %eventvalue2%=1
  //   Timerset,%eventvalue1%,[INT#7]
  // else
  //   Timerset,%eventvalue1%,0
  //   Let,7,0
  // endif
endon

on Rules#Timer do
  if %eventvalue%<7
    Let,%eventvalue%,0
    Let,7,0
    PcfGpio,%eventvalue%,0
    Event,AutoPrgWeiter
    Event,PumpeUndNT=0
  endif
endon

on PumpeUndNT do
  if %eventvalue1%=1
    Publish,/SW011/cmd,"event,Schalten=1"
    Gpio,13,1
  else
    if [VAR#1]=0 and [VAR#2]=0 and [VAR#3]=0 and [VAR#4]=0 and [VAR#5]=0 and [VAR#6]=0
      Publish,/SW011/cmd,"event,Schalten=0"
      Gpio,13,0
    endif
  endif  
endon

rules3.txt

Code: Select all

on AutoPrgStartStop do
  if %eventvalue1%<=0 and [Programm#lfdPrg]>0
    if [VAR#8]<>0
      TaskValueSet,8,3,[VAR#8] // Wiederherstellung alte Anpassung
      Let,8,0
    endif
    TaskValueSet,9,1,0
    if %eventvalue2%>0 and %eventvalue2%<=1
      TaskValueSet,8,3,%eventvalue2%
    endif
    Event,AutoPrgWeiter
  else
    if %eventvalue2%>0 and %eventvalue2%<=1
      if [Zeiten2#Anpassung]<>%eventvalue2%
        Let,8,[Zeiten2#Anpassung] // für Wiederherstellung merken
        TaskValueSet,8,3,%eventvalue2%
      endif
    endif
    if %eventvalue1%>0
      if [Programm#lfdPrg]<>%eventvalue1%
        TaskValueSet,9,1,%eventvalue1%
        Event,AutoPrgWeiter
      endif
    else
      if [Programm#lfdPrg]<>1
        TaskValueSet,9,1,1
        Event,AutoPrgWeiter
      endif
    endif
  endif
endon

on AutoPrgWeiter do
  if [Programm#lfdPrg]=0
    if [Programm#aktSeg]<>0
      Event,VentilSchalten=[Programm#aktSeg],0
      LogEntry,"Ventil [Programm#aktSeg] geschlossen"
      TaskValueSet,9,2,0
    endif
    LogEntry,"Programm gestoppt"
  else
    if [Programm#aktSeg]<>0
      Event,VentilSchalten=[Programm#aktSeg],0
      LogEntry,"Ventil [Programm#aktSeg] geschlossen"
    endif
    if [Programm#lfdPrg]=1
      Let,9,[Programm#aktSeg]+1
    endif
    if [Programm#lfdPrg]=2 or [Programm#lfdPrg]=3
      if [Programm#aktSeg]=0
        Let,9,1
      else
        Let,9,[Programm#aktSeg]+2
      endif
      if [Programm#lfdPrg]=3 and [INT#9]=7
        Let,9,[INT#9]-1
      endif
    endif
    if [INT#9]>6
      TaskValueSet,9,1,0
      Event,AutoPrgWeiter
    else
      TaskValueSet,9,2,[INT#9]
      Event,VentilSchalten=[INT#9],1
      LogEntry,"Programm [Programm#lfdPrg]/Ventil [Programm#aktSeg] geöffnet"
    endif
    Let,9,0
  endif
endon

[Ath]

The event handler PumpeUndNT has an if construction with too many conditions, a maximum of 3 conditions is supported. You'll have to break that up.
And you can't use arithmetic in those conditions (that would have been a simple fix).
If's can go up to 10 levels deep, so it is still quite easy to fix

[Micha_he]

But that if-construct works for month, without that I recognize any problems.
And in my tests, the event 'PumpeUndNT' is commented out (Line2 in event 'VentilSchalten').

Thanks, that you take a look in it.

[Ath]

Have you tried enabling all lines, except event,PumpeUndNT=%eventvalue2% in the VentilSchalten event handler? Those if's seem quite harmless, so I wouldn't expect it to crash.

There is also the ASyncEvent command, analog to the Event command, except it puts the event in the queue for processing, instead of calling it immediately (according to documentation, I didn't actually investigate this in the source), that could be worth a try.
The rules look like they should still work as intended when not being processed fully sequentially.
I've been experimenting with ASyncEvent too, as I also have a setup where events are triggered from events, and that has shown some instability (but not restarts, only event-storms), but that may also be caused by triggering events from another ESP unit...

[Micha_he]

Have you tried enabling all lines, except event,PumpeUndNT=%eventvalue2% in the VentilSchalten event handler?

When I habe only active the first (Let) Line, the event works. If I enable the third (same with second) line, the ESP reboots while the execution.

But I'll do a test and reduce the if-condition and report here...

Edit: No difference with changed if-condition !

[Ath]

Hmm, weird, one possibility could be that there are non-printable characters in your rules file, that won't show in the web editor. You'll need a proper editor (preferably Notepad++, View/Show Symbol/Show All Characters, but VS Code should be able to do that too), that can show non-printable characters, and all unexpected control-characters need to be removed.
It may also be advisable to check if the line ends used are Cr/Lf (Windows line ends), not Lf-only or Cr-only (Linux line ends or Mac line ends), as that may also cause unexpected trouble.

Ah, now I see this:

Code: Select all

Let,7,[Zeiten1#Dauer%eventvalue1%]*[Zeiten2#Anpassung]*60

I don't think that will work as expected, and may very well be the cause of the exceptions, you'll have to have separate statements for each Dauer1 to Dauer6

[TD-er]

I guess this is indeed the culprit:

Code: Select all

[Zeiten1#Dauer%eventvalue1%]

I don't even have a clue what it would be when it is acually being parsed.
The order in which things will be replaced does matter here.
So it is very well possible this was once working if the %eventvalue% would be converted into some int which would match a variable name (e.g. "Dauer1")

[Micha_he]

This line work flawlessly so far. (And is also commented out in the test).

You can reduce the event-rule to:

Code: Select all

on VentilSchalten do
  PcfGpio,1,0
endon

The reboot still happens.

No, non-pritable character and only windows-crlf.
Here are the rules as zip-package with reduced (mininmal) VentilSchalten-event-rule:

rules.zip

(1.3 KiB) Downloaded 285 times

Edit: And, the same rules (with original 'VentilSchalten') works, if I startet it via 'Event, VentilSchalten=1,1' under the webinterface/tools/command !

The problem exists only, if the event is executed via the event-rule 'AutoPrgWeiter' (Line 3,10,31)

[TD-er]

I'm currently to that sharp anymore as I would like to be, so I leave the checking for matching on...endon and if...endif to those that are.

Can you show some info on the used memory?
Especially the free stack.
I suspect you're running out of memory via a stack overflow.

Can you try to replace the Event commands with AsyncEvent ?

Edit:
There is also something fishy here:

Code: Select all

on AutoPrgWeiter do
[...]
    if [INT#9]>6
      TaskValueSet,9,1,0
      Event,AutoPrgWeiter
[...]

As you can see, this can cause an infinite loop (or recursion, which is also bad for the stack)

[Micha_he]

I'll try to reduce the test-environment to the needed dummy-device and the rules to a minimum tomorrow. Maybe that will help...

[TD-er]

Pleae see my edit too.

[Micha_he]

@TD-er: How I can be show the memory infos, before or until the reboot?

[Micha_he]

Code: Select all

on AutoPrgWeiter do
[...]
    if [INT#9]>6
      TaskValueSet,9,1,0
      Event,AutoPrgWeiter
[...]

As you can see, this can cause an infinite loop (or recursion, which is also bad for the stack)

No, the reloop is only executed once. At least it should...
In my tests I've disabled it, to rule it out as the problem. When I reduce the rules tommorow, I delete this part.

[TD-er]

@TD-er: How I can be show the memory infos, before or until the reboot?

That's hard, but I guess it may also run very low on memory when you do not yet crash and reboot.
So make sure you have the timingstats stuff enabled (not running the "testing" build) and then you can also see the lowest recorded free stack and heap values, including the function that was active at this lowest point.

When memory resources are suspect, you may also want to run with as few included plugins and controllers in your build as possible as those also use some memory even when not selected and enabled.

[Micha_he]

I've reduce the environment for some tests.
Factory reset, single PCF8574-device, simple test-rule, no ntp, no MQTT-controller.

Bewaesserung_Devices2.jpg (38.9 KiB) Viewed 20025 times

Bewaesserung_Device2.jpg (42.02 KiB) Viewed 20025 times

Code: Select all

on Test1 do
  Event,Test2
endon

on Test2 do
  Event,Test3
endon

on Test3 do
  Pcfgpio,1,[Ventil1#Status#!Z]
endon

Result: The roboot doesn't happen as often anymore, but after 2-25 execution of the command 'Event,Test1' via the tools-webpage, the reboot is done again !

Memory after reboot:

MemAfterReboot.jpg (15.87 KiB) Viewed 20025 times

Memory after 20 event-executions without watchdog-reboot:

MemAfter20.jpg (17.11 KiB) Viewed 20025 times

No more idea's... I'll change the ESP-WROOM02 to a ESP-12F and do another test.

[TD-er]

Are the MQTT messages sent to the broker?
Or are they all placed in a queue?

[Micha_he]

As long as I enabled the MQTT-Controller, the messages are sent faultless.

Edit: Found a difference. Now the reboot-reason isn't hardware-watchdog !?

Bewaesserung_RebootReason2.jpg (22 KiB) Viewed 20018 times

[TD-er]

That looks like it power cycled.

[Micha_he]

After re-enable the openHAB-controller again, the ESP rebooted after 3 event-commands and the reason is 'Hardware Watchdog' again.

Edit: Now ~20 event-commands later, nothing has changed, the next reboot. Reason 'Software/System restart' ???

I'll try another ESP...

[TD-er]

If it is crashing on HW watchdog too, then it could very well be a bug or a configuration issue.

Does it reconnect quite often to the MQTT broker?
Does it help if you continously send a ping to the node?

And can you post all of the rules you're now running?
And I don't see the build version mentioned.

[Micha_he]

No, it doesn't reconnect often to the MQTT broker.
All original rules are in post #1 of this thread. Last test-rule is in post #15.
Build is 'ESP_Easy_mega_20200913_normal_WROOM02_2M256.bin' from Github-release.

Ping... I've not tested, because no disconnections. Maybe a later idea.

[Micha_he]

Last test before I switch to the ESP-12F: No MQTT-disconnections while the last 13 hours. Thats not the reason.

Edit1: Changed to ESP-12F: Same problem tested with the simple rule from post #15)

Edit2: Custom-build with minimal plugin's didn't change anything.

[Micha_he]

New minimal setup:

ESP (WROOM02_2M256, but ESP12F is the same) flashed with the latest firmware. Config is DHCP, NTP with fritz.box and one device PCFGPIO-switch-input (Port 1, slow I2C speed, name=Ventil1, valuename=status). I mean, thats all.

One rule:

Code: Select all

on System#Boot do
  pcfgpio,1,0
endon

on Test1 do
  Event,Test2
endon

on Test2 do
  Event,Test3
endon

on Test3 do
  Pcfgpio,1,[Ventil1#Status#!Z]
endon

First I switch multiple with PCFGPIO-command, all is ok.

Ok.zip

(1.18 KiB) Downloaded 247 times

Now I use the event Test1 via tools/command: Event,Test1. The reboot ist done! Always. Here's the log with the exception-data:

Error_with_Event.zip

(15.54 KiB) Downloaded 234 times

The error can reproduce even without an existing PCF8574-device on the I2C-bus!

Help

[Micha_he]

Can I do some addional test to find the problem?
Can someone else reproduce the problem?

[Micha_he]

New insights:

The problem isn't dependent on the plugin 'Switch input - PCF8574' !!!

You can replace the only PCF8574-device with a simple switch input (e.g. name=switch, valuename=state, GPIO=12) and replace the second last line of the rule with 'GPIO,12,[Switch#State#!Z]'.

Event Test2 & Test3 works and event Test1 creates the exception.

[TD-er]

[...]
Event Test2 & Test3 works and event Test1 creates the exception.

That's causing a chain of events, so I guess you're creating a stack overflow there.
Is it really needed to have the events handled immediately?
If not, please call asyncevent instead of event, so the event will be queued.
This will make sure the rules parsing will not become recursive and thus use more stack.

See https://espeasy.readthedocs.io/en/lates ... nt-command

Using asyncevent will immediately return and place the event in a queue.
So you have to keep that in mind when writing the rules.
This implies the (async) event is not yet handled if you process the next command.

[Micha_he]

Maybe I can use AsyncEvent in the rules AS workaround. I'll look...

But how can one device and 12 lines (9 lines with the 3 events) create a stack overflow?
Is it possible, that the events are started too quickly after each other?

[Micha_he]

In my test-environment from the post above, the event-chain works, if I added a timer from 1s between the events.

It seems, that's the event-init or -execution is overlapping!

[TD-er]

Maybe I can use AsyncEvent in the rules AS workaround. I'll look...

But how can one device and 12 lines (9 lines with the 3 events) create a stack overflow?
Is it possible, that the events are started too quickly after each other?

Well we only have 4k stack in total on the ESP.
And the rules parsing does allocate quite a lot. So when you call an event from the rules, you essentially create a new rules parsing call. That one fires an event, so a new rules parsing instance. etc.

So they are not started too quickly, but are handled IMMEDIATELY.
That's exactly the reason I suggest to use the asyncevent as that one does schedule the event instead of processing it immediately.

[Micha_he]

But, when these events not executed too quick or the start didn't overlap, then that means, that 3 events being processed at the same time, cause the stack to overflow.

But if you think that this is not a bug in the parser, then I must switch to the AsyncEvent's... if It's possible in my irrigation-rules

[TD-er]

Well I do think it is undesired behavior for the unit to crash. So that crashing part is a bug.
But on the other hand, performing recursion via events in the rules processing is something you should try to avoid as we simply don't have a lot of resources on the ESP.

[Micha_he]

I've changed all events to async and it's working without crashes.