ESP32 resets on rules processing

Moderators: grovkillen, Stuntteam, TD-er

Post Reply
Message
Author
_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

ESP32 resets on rules processing

#1 Post by _Cyber_ » 28 Jan 2021, 22:37

hi,

If I call by http an event it is done partially, during the processing the esp32 reboots. :-(

here is a log of it. the log is from web, I do not know if it is complete.

Code: Select all

91244: Dummy: value 1: -1
91246: Dummy: value 2: 0
91247: Dummy: value 3: 0
91249: Dummy: value 4: 0
91265: EVENT: Z2#All=-1,0,0,0
91685: EVENT: Z3#All=-1,0,0,0
96006: WD : Uptime 2 ConnectFailures 0 FreeMem 205632 WiFiStatus WL_CONNECTED ESPeasy internal wifi status: Conn. IP Init
99887: HTTP: event,Closeall
99909: EVENT: closeall
99941: ACT : event,ControlZ1=100
99943: EVENT: ControlZ1=100
100111: ACT : Let,1,100
100362: ACT : logentry,Z1_c_comp
100364: Z1_c_comp
100366: ACT : gpio,2,0
100368: GPIO : port#2: set to 0
100370: ACT : TimerSet,8,20+2
100373: ACT : delay,250
100625: ACT : LongPulse,33,0,20
100628: GPIO : port 33. Pulse set for 20000 ms
100630: ACT : gpio,32,1
100632: GPIO : port#32: set to 1
100634: ACT : LongPulse,22,0,20
100636: GPIO : port 22. Pulse set for 20000 ms
100638: ACT : gpio,23,1
100639: GPIO : port#23: set to 1
100641: ACT : TimerSet,2,20
100645: ACT : TaskValueSet,2,4,1
100650: ACT : TaskValueSet,2,1,100
100655: ACT : TaskValueSet,2,2,100
100660: ACT : TaskValueSet,2,3,100
101224: ACT : event,ControlZ2=100
101226: EVENT: ControlZ2=100
101567: ACT : Let,4,100
101775: ACT : logentry,Z2_c_comp
101777: Z2_c_comp
101778: ACT : gpio,2,0
101780: GPIO : port#2: set to 0
101782: ACT : TimerSet,8,20+2
101786: ACT : delay,250
102038: ACT : LongPulse,13,0,20
102041: GPIO : port 13. Pulse set for 20000 ms
102043: ACT : gpio,27,1
102045: GPIO : port#27: set to 1
102047: ACT : LongPulse,26,0,20
102049: GPIO : port 26. Pulse set for 20000 ms
102051: ACT : gpio,25,1
102053: GPIO : port#25: set to 1
102055: ACT : TimerSet,4,20
102059: ACT : TaskValueSet,3,4,1
102065: ACT : TaskValueSet,3,1,100
102070: ACT : TaskValueSet,3,2,100
102075: ACT : TaskValueSet,3,3,100
4723: WIFI : Arduino wifi status: WL_CONNECTED ESPeasy internal wifi status: Conn.
4724: WIFI : DHCP IP: 192.168.10.233 (RollladenManager) GW: 192.168.10.1 SN: 255.255.255.0 duration: 24 ms
4735: WIFI : Arduino wifi status: WL_CONNECTED ESPeasy internal wifi status: Conn.
4736: WIFI : Scan finished, found: 5
4737: UDP : Start listening on port 8266
4737: firstLoopConnectionsEstablished
4764: Dummy: value 1: -1
4765: Dummy: value 2: 0
4790: Dummy: value 1: -1
4792: Dummy: value 2: 0
4794: Dummy: value 3: 0
4795: Dummy: value 4: 0
4820: Dummy: value 1: -1
4822: Dummy: value 2: 0
4823: Dummy: value 3: 0
4825: Dummy: value 4: 0
4849: Dummy: value 1: -1
4851: Dummy: value 2: 0
4852: Dummy: value 3: 0
4854: Dummy: value 4: 0
4878: Dummy: value 1: -1
4891: EVENT: TaskInit#SZ=1,0
5316: EVENT: TaskInit#Z1=2,0
5755: EVENT: TaskInit#Z2=3,0
6200: NTP : NTP replied: delay 10 mSec Accuracy increased by 0.971 seconds
6201: Time set to 1611869164.971
6202: Current Time Zone: DST time start: 2021-03-28 02:00:00 offset: 120 min STD time start: 2021-10-31 03:00:00 offset: 60 min
6203: Local time: 2021-01-28 22:26:04
6207: EVENT: Clock#Time=Thu,22:26
6703: EVENT: TaskInit#Z3=4,0
7168: WD : Uptime 0 ConnectFailures 0 FreeMem 205872 WiFiStatus WL_CONNECTED ESPeasy internal wifi status: Conn. IP Init
7179: EVENT: TaskInit#Boot=5,0
7662: EVENT: WiFi#ChangedAccesspoint
8088: EVENT: WiFi#ChangedWiFichannel
8506: EVENT: WiFi#Connected
8957: EVENT: SZ#All=-1,0
9384: EVENT: Z1#All=-1,0,0,0
9800: EVENT: Z2#All=-1,0,0,0
10246: EVENT: Z3#All=-1,0,0,0
10662: EVENT: Boot#All=-1
11079: EVENT: Time#Initialized
30225: Dummy: value 1: -1
30227: Dummy: value 2: 0
30238: EVENT: SZ#All=-1,0
30686: Dummy: value 1: -1
I am calling by http the event closeall which splits up in 4 events. those 4 events switch relays to close all shutters.

as the rules are quite big I did pastebins. rules2 to rules4 are the same, except other variables, other timers, other taskvaluesets and other gpio pins.

rules1: https://pastebin.com/pcBy5Dxi
rules2: https://pastebin.com/YdGDNZ7G
rules3: https://pastebin.com/BSR7P2hN
rules4: https://pastebin.com/5FhzVqfu

any ideas what is causing?

thanks. :-)

BR
Alois

sysinfo:

Code: Select all

{"System":{
"Build":20111,
"Git Build":"",
"System Libraries":"ESP32 SDK v3.2.3-14-gd3e562907",
"Plugin Count":47,
"Plugin Description":"[Normal]",
"Local Time":"2021-01-28 22:39:33",
"Unit Number":80,
"Unit Name":"RollladenManager",
"Uptime":13,
"Last Boot Cause":"Cold boot",
"Reset Reason":"CPU0: Software reset CPU CPU1: Software reset CPU",
"Load":23.33,
"Load LC":1187,
"CPU Eco Mode":"false",
"Free RAM":199256
},
"WiFi":{
"mDNS":"RollladenManager.local",
"IP Config":"DHCP",
"IP Address":"192.168.10.233",
"IP Subnet":"255.255.255.0",
"Gateway":"192.168.10.1",
"STA MAC":"7C:9E:BD:F8:F8:08",
"DNS 1":"192.168.10.1",
"DNS 2":"0.0.0.0",
"SSID":"KlinglAIRDMZUG",
"BSSID":"00:1F:F3:C1:F8:1A",
"Channel":2,
"Connected msec":810000,
"Last Disconnect Reason":1,
"Last Disconnect Reason str":"(1) Unspecified",
"Number Reconnects":0,
"Force WiFi B/G":"false",
"Restart WiFi Lost Conn":"false",
"Periodical send Gratuitous ARP":"false",
"Connection Failure Threshold":10,
"RSSI":-71
},
"nodes":[
{"nr":10,
"name":"WohnzimmerDimmer",
"build":20103,
"platform":"ESP Easy Mega",
"ip":"192.168.10.244",
"age":0
},{"nr":20,
"name":"Spieleraumheizung",
"build":20111,
"platform":"ESP Easy Mega",
"ip":"192.168.10.243",
"age":0
},{"nr":80,
"name":"RollladenManager",
"build":20111,
"platform":"ESP Easy 32",
"ip":"192.168.10.233",
"age":1
}],
"Sensors":[
{
"TaskValues": [
{"ValueNumber":1,
"Name":"S",
"NrDecimals":0,
"Value":-1
},
{"ValueNumber":2,
"Name":"M",
"NrDecimals":0,
"Value":0
}],
"DataAcquisition": [
{"Controller":1,
"IDX":0,
"Enabled":"false"
},
{"Controller":2,
"IDX":0,
"Enabled":"false"
},
{"Controller":3,
"IDX":0,
"Enabled":"false"
}],
"TaskInterval":30,
"Type":"Generic - Dummy Device",
"TaskName":"SZ",
"TaskDeviceNumber":33,
"TaskEnabled":"true",
"TaskNumber":1
},
{
"TaskValues": [
{"ValueNumber":1,
"Name":"S",
"NrDecimals":0,
"Value":-1
},
{"ValueNumber":2,
"Name":"SL",
"NrDecimals":0,
"Value":0
},
{"ValueNumber":3,
"Name":"SR",
"NrDecimals":0,
"Value":0
},
{"ValueNumber":4,
"Name":"M",
"NrDecimals":0,
"Value":0
}],
"DataAcquisition": [
{"Controller":1,
"IDX":0,
"Enabled":"false"
},
{"Controller":2,
"IDX":0,
"Enabled":"false"
},
{"Controller":3,
"IDX":0,
"Enabled":"false"
}],
"TaskInterval":30,
"Type":"Generic - Dummy Device",
"TaskName":"Z1",
"TaskDeviceNumber":33,
"TaskEnabled":"true",
"TaskNumber":2
},
{
"TaskValues": [
{"ValueNumber":1,
"Name":"S",
"NrDecimals":0,
"Value":-1
},
{"ValueNumber":2,
"Name":"SL",
"NrDecimals":0,
"Value":0
},
{"ValueNumber":3,
"Name":"SR",
"NrDecimals":0,
"Value":0
},
{"ValueNumber":4,
"Name":"M",
"NrDecimals":0,
"Value":0
}],
"DataAcquisition": [
{"Controller":1,
"IDX":0,
"Enabled":"false"
},
{"Controller":2,
"IDX":0,
"Enabled":"false"
},
{"Controller":3,
"IDX":0,
"Enabled":"false"
}],
"TaskInterval":30,
"Type":"Generic - Dummy Device",
"TaskName":"Z2",
"TaskDeviceNumber":33,
"TaskEnabled":"true",
"TaskNumber":3
},
{
"TaskValues": [
{"ValueNumber":1,
"Name":"S",
"NrDecimals":0,
"Value":-1
},
{"ValueNumber":2,
"Name":"SL",
"NrDecimals":0,
"Value":0
},
{"ValueNumber":3,
"Name":"SR",
"NrDecimals":0,
"Value":0
},
{"ValueNumber":4,
"Name":"M",
"NrDecimals":0,
"Value":0
}],
"DataAcquisition": [
{"Controller":1,
"IDX":0,
"Enabled":"false"
},
{"Controller":2,
"IDX":0,
"Enabled":"false"
},
{"Controller":3,
"IDX":0,
"Enabled":"false"
}],
"TaskInterval":30,
"Type":"Generic - Dummy Device",
"TaskName":"Z3",
"TaskDeviceNumber":33,
"TaskEnabled":"true",
"TaskNumber":4
},
{
"TaskValues": [
{"ValueNumber":1,
"Name":"Watcher",
"NrDecimals":0,
"Value":-1
}],
"DataAcquisition": [
{"Controller":1,
"IDX":0,
"Enabled":"false"
},
{"Controller":2,
"IDX":0,
"Enabled":"false"
},
{"Controller":3,
"IDX":0,
"Enabled":"false"
}],
"TaskInterval":60,
"Type":"Generic - Dummy Device",
"TaskName":"Boot",
"TaskDeviceNumber":33,
"TaskEnabled":"true",
"TaskNumber":5
}
],
"TTL":30000
}

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#2 Post by TD-er » 28 Jan 2021, 23:23

Without having looked at your rules (I will look at them), my first impression is that you may run into a loop.
E.g. calling an event (instead of asyncevent) which calls another event, etc.

If you use asyncevent instead of event, then the event will be added to an event queue and thus the initial called event will return before the newly fired event is executed.

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#3 Post by TD-er » 28 Jan 2021, 23:30

Yep, the "openall" and "closeall" are perfect candidates for an "asyncevent"

Code: Select all

on Openall do
 //control?cmd=event,Openall
 event,ControlZ1=0
 event,ControlZ2=0
 event,ControlZ3=0
 event,ControlSZ=0
endon
 
on Closeall do
 //control?cmd=event,Closeall
 event,ControlZ1=100
 event,ControlZ2=100
 event,ControlZ3=100
 event,ControlSZ=100
endon
 
And maybe you can make a single event handler to avoid a lot of code duplication?

For example you can create small event wrappers to call the generic one with a few more arguments.
In those arguments you can then add some info as to in what variables you store states.
For example "[VAR#13]" can be written as "[VAR#%v1%]" where variable#1 stored "13".

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#4 Post by TD-er » 28 Jan 2021, 23:32

Ah in your 2nd pastebin link you appear to be using a delay command.

Please set a timer and don't use delay.
The timers also have a version with "_ms" suffix.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#5 Post by _Cyber_ » 29 Jan 2021, 10:50

asyncevent: will try this, thanks. :-)

the avoiding code duplication is on my list, I will try to make completely rules 2, 3 and 4 into one ruleset. thanks for the hints with substituting variable numbers with variables. :-)

the delay: I have already all possible 8 timers in use, over the 4 rulesets. or is the limitation per ruleset? but that's the reason for using delay here.
all other events are working with the delay, only the event calling events was affected. so I keep my fingers crossed to have it solved by asyncevent.

BR
Alois

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#6 Post by TD-er » 29 Jan 2021, 10:54

I can increase the number of timers.
It is now stored in a vector, so there is not really a reason for having a low limit for it anymore.
But that's not present in current builds, so that should be done in a new build.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#7 Post by _Cyber_ » 29 Jan 2021, 16:25

using asyncevent solved the issue. :-)

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#8 Post by TD-er » 29 Jan 2021, 16:51

Great :)

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#9 Post by _Cyber_ » 08 Feb 2021, 16:13

@TD-er may I ask, how long are single events allowed to block until the unit reset?

e.g. the following part of rules:

Code: Select all

   logentry,%syssec%
   event,ControlZ1L=[VAR#2]
   logentry,%syssec%
   event,ControlZ1R=[VAR#2]
   logentry,%syssec%
gives me output:

Code: Select all

18249531: ACT : logentry,'Z1SL=11.00 and Z1SR=78.00 not in same state. Drive independently.'
18249533: Z1SL=11.00 and Z1SR=78.00 not in same state. Drive independently.
18249535: ACT : Let,1,-1
18249539: ACT : Let,2,50
18249845: ACT : logentry,59
18249847: 59
18249850: ACT : event,ControlZ1L=50
18249852: EVENT: ControlZ1L=50
18250189: ACT : logentry,Z1L_c_secs=7.01999998092651
18250191: Z1L_c_secs=7.01999998092651
18250192: ACT : gpio,2,0
18250194: GPIO : port#2: set to 0
18250196: ACT : TimerSet,8,7
18250199: ACT : TaskValueSet,2,4,1
18250203: ACT : delay,250
18250456: ACT : LongPulse,22,0,7
18250458: GPIO : port 22. Pulse set for 7000 ms
18250460: ACT : gpio,23,1
18250461: GPIO : port#23: set to 1
18250463: ACT : Let,33,7
18250467: ACT : Let,34,1
18250476: ACT : loopTimerSet_ms,2,1000,7
18250584: ACT : logentry,59
18250585: 59
18250587: ACT : event,ControlZ1R=50
18250590: EVENT: ControlZ1R=50
18250828: ACT : Let,1,50
18250837: ACT : Let,10,(18/100)*50
18250873: ACT : Let,11,(18/100)*78.00
18250882: ACT : Let,12,14.04-9
18250889: ACT : logentry,Z1R_o_secs=5.03999996185303
18250891: Z1R_o_secs=5.03999996185303
18250893: ACT : gpio,2,0
18250895: GPIO : port#2: set to 0
18250898: ACT : TimerSet,8,5
18250901: ACT : TaskValueSet,2,4,1
18250905: ACT : delay,250
18251158: ACT : LongPulse,33,0,5
18251161: GPIO : port 33. Pulse set for 5000 ms
18251164: ACT : LongPulse,32,0,5
18251166: GPIO : port 32. Pulse set for 5000 ms
18251169: ACT : Let,36,5
18251173: ACT : Let,37,-1
18251180: ACT : logentry,'Z1_Timer already set'
18251183: Z1_Timer already set
18251294: ACT : logentry,59
18251295: 59
18251380: EVENT: Clock#Time=Mon,16:01
18251405: ACT : asyncevent,updatephp
18251701: EVENT: updatephp
from this I can see:
18249845: ACT : logentry,59
18250584: ACT : logentry,59
18251294: ACT : logentry,59

18251294 - 18250584 --> 710ms sub-event processing time (yes, I know, still working with delay)
18250584 - 18249845 --> 739ms sub-event processing time (yes, I know, still working with delay)

additionally what I do not know: is the sub-event completely blocking (and e.g. watchdog resets the unit after 1000ms) or is there in between time for watchdog to recover?

Thank you. :-)

BR
Alois

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#10 Post by TD-er » 08 Feb 2021, 16:40

Well it is a bit hard to tell what will cause the watchdog reset and what not.

The SW watchdog (software) is set to roughly 2 seconds.
Hardware watchdog (HW watchdog) is set to roughly 6 seconds (on the ESP8266 at least, not sure if ESP32 uses a different setting)

A call to delay() should feed the watchdog.
This is called a lot of times in the code, so some commands may block for like 10+ seconds and still not trigger a reboot, while others may cause a reboot.

For example when connecting to a host, the code should call a number of delay() calls when trying to connect.
Also the WiFiClient used in controllers or when you try to connect to a host, is given a timeout (timeout set in the controller for example).
As some calls to WiFiClient are blocking too, which thus need to rely on the set timeout.
However, I have noticed that some calls (like trying to connect) may not obey this set timeout and also not call delay() and thus cause a watchdog reboot.
That's one of the reasons why I do call a check to see if we're still connected so often. (see timing stats, to see how often)

Still it is best practice to use asynevent where possible.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#11 Post by _Cyber_ » 09 Feb 2021, 07:34

TD-er wrote: 28 Jan 2021, 23:30 And maybe you can make a single event handler to avoid a lot of code duplication?

For example you can create small event wrappers to call the generic one with a few more arguments.
In those arguments you can then add some info as to in what variables you store states.
For example "[VAR#13]" can be written as "[VAR#%v1%]" where variable#1 stored "13".
on trying this, I am stumbling over this:

Setting the taskvalue I need to: TaskValueSet,1,1,100

I need to replace the numbers by Variables, this works in setting taskvalues:
TaskValueSet,[VAR#1],[VAR#2],100

but recalling the TaskValue needs chars: Let,11,(28/100)*[SZ#S]

How can I recall the TaskValues with numbers to have it in the same variables?
I tried [1#1] but it didn't work ...

Thanks :-)

BR
Alois

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#12 Post by TD-er » 09 Feb 2021, 09:13

You can't.
We don't have a "taskvalueget" function and numbers are not allowed as task name or taskvalue name.

But I can see why it could be useful when you use the variables to get/set dummy values.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#13 Post by _Cyber_ » 09 Feb 2021, 11:19

:shock:

any ideas how I can circumvent?

currently I have the following codeblock which is used 7 times identically with the following changing parts:

[VAR#33] seconds Z1L requested
[VAR#34] direction Z1L
[VAR#35] Z1L shutters percent
(loop)TimerSet_ms,2 will be (loop)TimerSet_ms,[VAR#XXX]
two unshared GPIOs used (22, 23) (GPIO 2 is shared between all codeblocks)
"18" which will be [VAR#YYY]
TaskValueSet where only the device changes, not the Variable name
each "[Z1#S]", "[Z1#SL]", "[Z1#SR]" and "[Z1#M]"

als the timercodeblock is identically 4 times, only the vars and devices are changing.

with the code duplication ruleparsing gets very slow - as long as I have the codeblock only 3 times in rules the LoopTimer (one instance) is in time, with all 7 instances and the 4 timers in rules, but only one LoopTimer_ms active, it is delayed - I suspect the ruleparsing and the code duplication is the reason ... ?

Thanks :-)

BR
Alois

eventcodeblock:

Code: Select all

on ControlZ1L do
 //control?cmd=event,ControlZ1L=0
 // control only left shutter, in percent.
 if %eventvalue% > 0 and %eventvalue% < 100 and [VAR#33] = 0
  //open/close percent
  Let,10,(18/100)*%eventvalue%
  Let,11,(18/100)*[Z1#SL]
  if [VAR#11] > [VAR#10]
   // open a bit
   Let,12,[VAR#11]-[VAR#10]
   if [INT#12] > 0
    logentry,Z1L_o_secs=[VAR#12]
    gpio,2,0
    TimerSet,8,[INT#12]
    TaskValueSet,2,4,1
    delay,250
    LongPulse,22,0,[INT#12]
    LongPulse,23,0,[INT#12]
	Let,33,[INT#12]
	Let,34,-1
    if [VAR#36] > [INT#12]
     logentry,"Z1_Timer already set"
    else
     loopTimerSet_ms,2,1000,[INT#12]
    endif
   else
    logentry,"Z1L_o_secs below 1, nothing to do"
	TaskValueSet,2,2,%eventvalue%
   endif
  endif
  if [VAR#11] < [VAR#10]
   //close a bit
   Let,12,[VAR#10]-[VAR#11]
   if [INT#12] > 0
    logentry,Z1L_c_secs=[VAR#12]
    gpio,2,0
    TimerSet,8,[INT#12]
    TaskValueSet,2,4,1
    delay,250
    LongPulse,22,0,[INT#12]
    gpio,23,1
	Let,33,[INT#12]
	Let,34,1
    if [VAR#36] > [INT#12]
     logentry,"Z1_Timer already set"
    else
     loopTimerSet_ms,2,1000,[INT#12]
    endif
   else
    logentry,"Z1L_c_secs below 1, nothing to do"
	TaskValueSet,2,2,%eventvalue%
   endif
  endif
 else
  if %eventvalue% = 0 and [VAR#33] = 0
   // open left shutter complete
   logentry,Z1L_o_comp
   Let,12,18
   gpio,2,0
   TimerSet,8,[INT#12]
   TaskValueSet,2,4,1
   delay,250
   LongPulse,22,0,[INT#12]
   LongPulse,23,0,[INT#12]
   Let,33,[INT#12]
   Let,34,-1
   if [VAR#36] > [INT#12]
    logentry,"Z1_Timer already set"
   else
    loopTimerSet_ms,2,1000,[INT#12]
   endif
  endif
  if %eventvalue% = 100 and [VAR#33] = 0
   // close left shutter complete
   logentry,Z1L_c_comp
   Let,12,18
   gpio,2,0
   TimerSet,8,[INT#12]
   TaskValueSet,2,4,1
   delay,250
   LongPulse,22,0,[INT#12]
   gpio,23,1
   Let,33,[INT#12]
   Let,34,1
   if [VAR#36] > [INT#12]
    logentry,"Z1_Timer already set"
   else
    loopTimerSet_ms,2,1000,[INT#12]
   endif
  endif
  if %eventvalue% = 101
   //stop Z1L
   logentry,Z1L_stop
   LongPulse,22,0,0
   LongPulse,23,0,0
   Let,33,0
  endif
  if %eventvalue% = 102
   //special state
  endif
  if %eventvalue% = 103
   //special state
  endif
 endif
endon
timercodeblock:

Code: Select all

on Rules#Timer=2 do
 Let,33,[VAR#33]-1
 Let,36,[VAR#36]-1

 Let,35,[Z1#SL]+(100/18)*[VAR#34]
 if [VAR#33] <= 0
  Let,33,0
  Let,34,0
  if [VAR#35] >= 0 and [VAR#35] <= 100
   TaskValueSet,2,2,[INT#35]
   TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
  else
   if [VAR#35] <= 0
    TaskValueSet,2,2,0
    TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
   else
    TaskValueSet,2,2,100
	TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
   endif
  endif
 else
  if [VAR#35] >= 0 and [VAR#35] <= 100
   TaskValueSet,2,2,[VAR#35]
   TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
  else
   if [VAR#35] <= 0
    TaskValueSet,2,2,0
	TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
   else
    TaskValueSet,2,2,100
	TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
   endif
  endif
 endif
 
 Let,38,[Z1#SR]+(100/18)*[VAR#37]
 if [VAR#36] <= 0
  Let,36,0
  Let,37,0
  if [VAR#38] >= 0 and [VAR#38] <= 100
   TaskValueSet,2,3,[INT#38]
   TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
  else
   if [VAR#38] <= 0
    TaskValueSet,2,3,0
	TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
   else
    TaskValueSet,2,3,100
	TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
   endif
  endif
 else
  if [VAR#38] >= 0 and [VAR#38] <= 100
   TaskValueSet,2,3,[VAR#38]
   TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
  else
   if [VAR#38] <= 0
    TaskValueSet,2,3,0
	TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
   else
    TaskValueSet,2,3,100
	TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
   endif
  endif
 endif
 
 if [VAR#33] <= 0 and [VAR#36] <= 0
  TaskValueSet,2,4,0
  TimerSet_ms,2,0
 endif
 SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=%sysname%&Z1=[Z1#M];[Z1#S];[Z1#SL];[Z1#SR];
endon

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#14 Post by TD-er » 09 Feb 2021, 12:05

I have not looked into your rules in very great detail, but based on what you're asking you would like to replace some variables used in every block only using a different variable?

So why not handle the event in 2 stages? (for this you need to have a normal event, not an asyncevent)

Something like this:

Code: Select all

on ControlZ1L do
  // Using some offset in var nr, you must define your own
  let,20,[Z1#SL]
  event,HandleAllControl=%eventvalue1%
endon

on HandleAllControl do
  // Your generic event block, referring [var#20]

endon

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#15 Post by _Cyber_ » 09 Feb 2021, 12:39

I tried, but as soon as I have in rules e.g.

Code: Select all

 Let,10,[Z1#S]
 Let,11,[Z1#SL]
 Let,12,[Z1#SR]
 Let,13,[Z1#M]
ruleparsing stops and nothing happens. from the rules :-/

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#16 Post by TD-er » 09 Feb 2021, 12:52

What is the type of these task values?
What plugin are they using?

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#17 Post by _Cyber_ » 09 Feb 2021, 12:56

this are all dummy devices, Output Data type is set to "Quad", Values are either 0 or 2 decimal.

here the json; the "TaskName":"SZ" will be changed from 2 to 4 values.

Code: Select all

"Sensors":[
{
"TaskValues": [
{"ValueNumber":1,
"Name":"S",
"NrDecimals":2,
"Value":50.00
},
{"ValueNumber":2,
"Name":"M",
"NrDecimals":0,
"Value":0
}],
"DataAcquisition": [
{"Controller":1,
"IDX":0,
"Enabled":"false"
},
{"Controller":2,
"IDX":0,
"Enabled":"false"
},
{"Controller":3,
"IDX":0,
"Enabled":"false"
}],
"TaskInterval":30,
"Type":"Generic - Dummy Device",
"TaskName":"SZ",
"TaskDeviceNumber":33,
"TaskEnabled":"true",
"TaskNumber":1
},
{
"TaskValues": [
{"ValueNumber":1,
"Name":"S",
"NrDecimals":2,
"Value":100.00
},
{"ValueNumber":2,
"Name":"SL",
"NrDecimals":2,
"Value":100.00
},
{"ValueNumber":3,
"Name":"SR",
"NrDecimals":2,
"Value":100.00
},
{"ValueNumber":4,
"Name":"M",
"NrDecimals":0,
"Value":0
}],
"DataAcquisition": [
{"Controller":1,
"IDX":0,
"Enabled":"false"
},
{"Controller":2,
"IDX":0,
"Enabled":"false"
},
{"Controller":3,
"IDX":0,
"Enabled":"false"
}],
"TaskInterval":30,
"Type":"Generic - Dummy Device",
"TaskName":"Z1",
"TaskDeviceNumber":33,
"TaskEnabled":"true",
"TaskNumber":2
},
{
"TaskValues": [
{"ValueNumber":1,
"Name":"S",
"NrDecimals":2,
"Value":100.00
},
{"ValueNumber":2,
"Name":"SL",
"NrDecimals":2,
"Value":100.00
},
{"ValueNumber":3,
"Name":"SR",
"NrDecimals":2,
"Value":100.00
},
{"ValueNumber":4,
"Name":"M",
"NrDecimals":0,
"Value":0
}],
"DataAcquisition": [
{"Controller":1,
"IDX":0,
"Enabled":"false"
},
{"Controller":2,
"IDX":0,
"Enabled":"false"
},
{"Controller":3,
"IDX":0,
"Enabled":"false"
}],
"TaskInterval":30,
"Type":"Generic - Dummy Device",
"TaskName":"Z2",
"TaskDeviceNumber":33,
"TaskEnabled":"true",
"TaskNumber":3
},
{
"TaskValues": [
{"ValueNumber":1,
"Name":"S",
"NrDecimals":2,
"Value":100.00
},
{"ValueNumber":2,
"Name":"SL",
"NrDecimals":2,
"Value":100.00
},
{"ValueNumber":3,
"Name":"SR",
"NrDecimals":2,
"Value":100.00
},
{"ValueNumber":4,
"Name":"M",
"NrDecimals":0,
"Value":0
}],
"DataAcquisition": [
{"Controller":1,
"IDX":0,
"Enabled":"false"
},
{"Controller":2,
"IDX":0,
"Enabled":"false"
},
{"Controller":3,
"IDX":0,
"Enabled":"false"
}],
"TaskInterval":30,
"Type":"Generic - Dummy Device",
"TaskName":"Z3",
"TaskDeviceNumber":33,
"TaskEnabled":"true",
"TaskNumber":4
}
],
"TTL":30000
}
Last edited by _Cyber_ on 09 Feb 2021, 13:06, edited 1 time in total.

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#18 Post by TD-er » 09 Feb 2021, 13:06

What version are you running?
And can you try to include an "=" in the let commands like this?

Code: Select all

 Let,10,=[Z1#S]
 Let,11,=[Z1#SL]
 Let,12,=[Z1#SR]
 Let,13,=[Z1#M]
 

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#19 Post by _Cyber_ » 09 Feb 2021, 13:14

running ESP_Easy_mega_20210114_normal_ESP32_4M316k

it's working with Let,10,=[Z1#S]

thanks - again on typing rules :D

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#20 Post by _Cyber_ » 09 Feb 2021, 22:25

ok, now I have compacted the code and wrapped stuff in events which I call. I have now instead of 28kb rules only 14kb left. :D

the rules are now unreadable. should not harm, as long as they are working.
but, there is an issue, and, I was able to track it down, I cannot believe.

Code: Select all

24777148: ACT : Let,66,20
24777152: ACT : Let,67,21
24777156: ACT : Let,68,22
24777159: ACT : event,StateShutter
24777161: EVENT: StateShutter
24777358: ACT : Let,20,4-1
24777365: ACT : Let,22,(0+(100/28)*)
24777371: ACT : logentry,'VAR#v67=1'
24777373: VAR#v67=1
24777421: ACT : TaskValueSet,1,2,0
24777428: ACT : TaskValueSet,1,1,((0+0)/2)
24778012: EVENT: Rules#Timer=7,12
look ath the lines
24777152: ACT : Let,67,21
24777365: ACT : Let,22,(0+(100/28)*)
24777371: ACT : logentry,'VAR#v67=1'

the corresponding code is:

Code: Select all

 Let,67,21 // Timer shutter direction VAR Number
 Let,%v68%,([VAR#64]+(100/[VAR#60])*[VAR#%v67%])
 logentry,"VAR#v67=[VAR#%v67%]"
what puzzles me: [VAR#%v67%] should translate to [VAR#21] and [VAR#21] has value "1"

it does so on timestamp 24777371

it does not so a line above, at timestamp 24777365 .... there it is just "nothing".

have tried already with and without (), moving [VAR#%v67%] in front of the calculation, etc ... does not help at all.

what have I done wrong?

thanks! :-)

BR
Alois

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#21 Post by TD-er » 09 Feb 2021, 23:20

Can you check on the system variables page to see what values all vars have?
I still have to check the numerical parsing as another user reported something funky with command parsing too.

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#22 Post by TD-er » 10 Feb 2021, 00:41

I did test this:

Code: Select all

 on eventname do
   let,1,2
   let,%v1%,4
   let,3,[int#%v1%]
   LogEntry,'Test Var: [var#3]  pct_v: %v3%'
 endon
What you should take into account is that referring a variable which was not set will return 0.0
See the system variables page to see what variables are set.

To make sure the "Let" command is not acting strange, you should use the [int#...] notation to make sure the variables are converted into an int when used as a parameter that should be an int (as variable index for example)

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#23 Post by _Cyber_ » 10 Feb 2021, 06:17

sorry, I forgot this to mention: in system variables I can see the vars filled correct:
%v67% has 21
%v21% has 1

I tried with INT instead of VAR, does not change anything. and, for the logentry, it is is correct resolved, but not for the calculation. it is not resolved as 0.0 or 0, it is just "".
I did also try with "+" instead of "*" - did also not change anything.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#24 Post by _Cyber_ » 10 Feb 2021, 07:01

moved now all VAR to INT which are supposed to have no floats, did not help.

here is the code where I trigger the StateShutter calculate-event:

Code: Select all

on Rules#Timer=7 do
 Let,60,28 // full open/close duration
 Let,61,1  // Taskvalue Device
 Let,62,2  // Taskvalue Variable
 Let,64,=[SZ#S1] // Current shutter state
 Let,65,=[SZ#S1] // Current partnershutter state
 Let,66,20 // Timer Seconds requested VAR Number
 Let,67,21 // Timer shutter direction VAR Number
 Let,68,22 // Timer shutter percent VAR Number
 event,StateShutter
 if [VAR#20] <= 0
  TaskValueSet,1,4,0
  TimerSet_ms,7,0
 endif
 //SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=%sysname%&SZ=[SZ#M];[SZ#S];
endon
it is intended to have Let,64 and Let,65 referencing in this case the same Dummydevice-Value; 64 and 65 and the reference to 68 are the only float, all others are int. The reference to 67 is either -1 or 1

and here is the StateShutter event:

Code: Select all

on StateShutter do
 Let,%v66%,[INT#%v66%]-1
 Let,%v68%,([VAR#64]+(100/[INT#60])*[INT#%v67%])
 logentry,"VAR#v67=[INT#%v67%]"
 if [INT#%v66%] <= 0
  if [VAR#%v68%] >= 0 and [VAR#%v68%] <= 100
   TaskValueSet,[INT#61],[INT#62],[VAR#%v68%]
   TaskValueSet,[INT#61],1,(([VAR#%v68%]+[VAR#65])/2)
  else
   if [VAR#%v68%] <= 0
    TaskValueSet,[INT#61],[INT#62],0
    TaskValueSet,[INT#61],1,(([VAR#65])/2)
   else
    TaskValueSet,[INT#61],[INT#62],100
    TaskValueSet,[INT#61],1,(([100+[VAR#65])/2)
   endif
  endif
 else
  if [VAR#%v68%] >= 0 and [VAR#%v68%] <= 100
   TaskValueSet,[INT#61],[INT#62],[VAR#%v68%]
   TaskValueSet,[INT#61],1,(([VAR#%v68%]+[VAR#65])/2)
  else
   if [VAR#%v68%] <= 0
    TaskValueSet,[INT#61],[INT#62],0
    TaskValueSet,[INT#61],1,(([VAR#65])/2)
   else
    TaskValueSet,[INT#61],[INT#62],100
    TaskValueSet,[INT#61],1,((100+[VAR#65])/2)
   endif
  endif
 endif
endon
{/code]

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#25 Post by _Cyber_ » 10 Feb 2021, 07:21

I just found out: if I assign the value before to a variable and use the Variable instead of the reference it works.

so, this works:

Code: Select all

 Let,11,[INT#%v67%]
 Let,%v68%,([VAR#64]+(100/[INT#60])*[INT#11])
 logentry,"VAR#v67=[INT#%v67%]"

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#26 Post by TD-er » 10 Feb 2021, 10:09

OK, that sounds like a bug or at least an undocumented feature...

I will have a look at the order in which items are being replaced and also if I need to call it several times to replace all occurences in a single line.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#27 Post by _Cyber_ » 10 Feb 2021, 14:42

TD-er wrote: 10 Feb 2021, 10:09 OK, that sounds like a bug or at least an undocumented feature...

I will have a look at the order in which items are being replaced and also if I need to call it several times to replace all occurences in a single line.
shall I open a issue on github regarding this?


hm, so I have now compacted the code as best as possible, it works, but if I try to drive the shutters parallel (below in the code the "Openall" or "Closeall") the tasks are very, very slow.
the PulseGPIO is in time, so the GPIOs are set back after the configured time.

but the task which calculate the percentage are not finished after the expected 28 seconds latest, but need instead 2min 30sec

the HTTP requests in timer7 are not the delayer - even without them it needs ages.

any ideas what I can tweak here?
what is the performance-consuming part?

Thanks - and sorry, I don't know if it is was ever planned to have such rules ...

:D :o :shock:

Code: Select all

on Clock#Time=All,%sunset% do
 asyncevent,Closeall
endon

on Clock#Time=All,**:** do
 SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=%sysname%&ipv4=%ip%&uptime=%uptime%&load=%sysload%&freeram=%sysheap%&rssi=%rssi%&SZ=[SZ#M];[SZ#S];&Z1=[Z1#M];[Z1#S];[Z1#SL];[Z1#SR];&Z2=[Z2#M];[Z2#S];[Z2#SL];[Z2#SR];&Z3=[Z3#M];[Z3#S];[Z3#SL];[Z3#SR];
endon

on Closeall do
 asyncevent,ControlSZ=100
 asyncevent,ControlZ1=100
 asyncevent,ControlZ2=100
 asyncevent,ControlZ3=100
endon

on Openall do
 asyncevent,ControlSZ=0
 asyncevent,ControlZ1=0
 asyncevent,ControlZ2=0
 asyncevent,ControlZ3=0
endon

on Rules#Timer=8 do
 if [Z1#M] = 0 and [Z2#M] = 0 and [Z3#M] = 0 and [SZ#M] = 0
  logentry,"No Movement, Power off"
  gpio,2,1
 else
  logentry,"Power still needed (SZ#M=[SZ#M] Z1#M=[Z1#M] Z2#M=[Z2#M] Z3#M=[Z3#M])"
  TimerSet,8,1
 endif
 SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=%sysname%&ipv4=%ip%&uptime=%uptime%&load=%sysload%&freeram=%sysheap%&rssi=%rssi%&SZ=[SZ#M];[SZ#S];&Z1=[Z1#M];[Z1#S];[Z1#SL];[Z1#SR];&Z2=[Z2#M];[Z2#S];[Z2#SL];[Z2#SR];&Z3=[Z3#M];[Z3#S];[Z3#SL];[Z3#SR];
endon

on Rules#Timer=7 do
 if [VAR#20] <= 0 or [VAR#33] <= 0 or [VAR#36] <= 0 or [VAR#43] <= 0 or [VAR#46] <= 0 or [VAR#53] <= 0 or [VAR#56] <= 0
  TimerSet,7,0
 endif
 SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=%sysname%&ipv4=%ip%&uptime=%uptime%&load=%sysload%&freeram=%sysheap%&rssi=%rssi%&SZ=[SZ#M];[SZ#S];&Z1=[Z1#M];[Z1#S];[Z1#SL];[Z1#SR];&Z2=[Z2#M];[Z2#S];[Z2#SL];[Z2#SR];&Z3=[Z3#M];[Z3#S];[Z3#SL];[Z3#SR];
endon

on Rules#Timer=1 do
 Let,60,28 // full open/close duration
 Let,61,1  // Taskvalue Device
 Let,62,2  // Taskvalue Variable
 Let,63,=[SZ#S1] // Current shutter state
 Let,64,20 // Timer Seconds requested VAR Number
 Let,65,21 // Timer shutter direction VAR Number
 Let,66,22 // Timer shutter percent VAR Number
 event,StateShutter
 TaskValueSet,1,1,[SZ#S1]
 if [VAR#20] <= 0
  TaskValueSet,1,4,0
  TimerSet_ms,1,0
 endif
 //SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=%sysname%&SZ=[SZ#M];[SZ#S];
endon

on ControlSZ do
 //control?cmd=event,ControlSZ=0
 Let,2,4 // GPIO 1
 Let,3,16 // GPIO 2
 Let,4,28 // full open/close duration
 Let,5,1  // Taskvalue Device and TimerIDX
 Let,6,2  // Taskvalue Variable
 Let,7,=[SZ#S1] // Current shutter state
 Let,8,20 // Timer Seconds requested VAR Number
 Let,9,21 // Timer shutter direction VAR Number
 Let,10,22 // timershared shutter VAR Number
 event,ControlShutter=%eventvalue%
endon

on ControlShutter do
 //control?cmd=event,ControlShutter=0
 // control shutter, in percent.
 if %eventvalue% > 0 and %eventvalue% < 100 and [INT#%v8%] = 0
  //open/close percent
  Let,13,([INT#4]/100)*%eventvalue%
  Let,14,([INT#4]/100)*[VAR#7]
  if [VAR#14] > [VAR#13]
   // open a bit
   Let,12,[VAR#14]-[VAR#13]
   if [INT#12] > 0
    //logentry,"GPIO=[INT#2],[INT#3]_open_secs=[VAR#12]"
    gpio,2,0
    TimerSet,8,[INT#12]
    TaskValueSet,[INT#5],4,1
    delay,250
    LongPulse,[INT#2],0,[INT#12]
    LongPulse,[INT#3],0,[INT#12]
    Let,%v8%,[INT#12]
    Let,%v9%,-1
    if [INT#%v10%] > [INT#12]
     logentry,"TimerIDX [INT#5] already set"
    else
     loopTimerSet_ms,[INT#5],1000,[INT#12]
    endif
   else
    //logentry,"GPIO=[INT#2],[INT#3]open_secs below 1, nothing to do"
    TaskValueSet,[INT#5],[INT#6],%eventvalue%
   endif
  endif
  if [VAR#14] < [VAR#13]
   //close a bit
   Let,12,[VAR#13]-[VAR#14]
   if [INT#12] > 0
    //logentry,"GPIO=[INT#2],[INT#3]_close_secs=[VAR#12]"
    gpio,2,0
    TimerSet,8,[INT#12]
    TaskValueSet,[INT#5],4,1
    delay,250
    LongPulse,[INT#2],0,[INT#12]
    gpio,[INT#3],1
    Let,%v8%,[INT#12]
    Let,%v9%,1
    if [INT#%v10%] > [INT#12]
     logentry,"TimerIDX [INT#5] already set"
    else
     loopTimerSet_ms,[INT#5],1000,[INT#12]
    endif
   else
    //logentry,"GPIO=[INT#2],[INT#3]_close_secs below 1, nothing to do"
    TaskValueSet,[INT#5],[INT#6],%eventvalue%
   endif
  endif
 else
  if %eventvalue% = 0 and [INT#%v8%] = 0
   // open shutter complete
   //logentry,"GPIO=[INT#2],[INT#3]_open_complete"
   Let,12,[INT#4]
   gpio,2,0
   TimerSet,8,[INT#12]
   TaskValueSet,[INT#5],4,1
   delay,250
   LongPulse,[INT#2],0,[INT#12]
   LongPulse,[INT#3],0,[INT#12]
   Let,%v8%,[INT#12]
   Let,%v9%,-1
   if [INT#%v10%] > [INT#12]
    logentry,"TimerIDX [INT#5] already set"
   else
    loopTimerSet_ms,[INT#5],1000,[INT#12]
   endif
  endif
  if %eventvalue% = 100 and [INT#%v8%] = 0
   // close shutter complete
   //logentry,"GPIO=[INT#2],[INT#3]_close_complete"
   Let,12,[INT#4]
   gpio,2,0
   TimerSet,8,[INT#12]
   TaskValueSet,[INT#5],4,1
   delay,250
   LongPulse,[INT#2],0,[INT#12]
   gpio,[INT#3],1
   Let,%v8%,[INT#12]
   Let,%v9%,1
   if [INT#%v10%] > [INT#12]
    logentry,"TimerIDX [INT#5] already set"
   else
    loopTimerSet_ms,[INT#5],1000,[INT#12]
   endif
  endif
  if %eventvalue% = 101
   //stop shutter
   //logentry,"GPIO=[INT#2],[INT#3]_stop"
   LongPulse,[INT#2],0,0
   LongPulse,[INT#3],0,0
   Let,%v8%,0
  endif
  if %eventvalue% = 102
   //special state
  endif
  if %eventvalue% = 103
   //special state
  endif
 endif
 TimerSet,7,1
endon

on StateShutter do
 Let,%v64%,[INT#%v64%]-1
 Let,11,[INT#%v65%]
 Let,%v66%,([VAR#63]+(100/[INT#60])*[INT#11])
 if [INT#%v64%] <= 0
  Let,%v64%,0
  Let,%v65%,0
  if [VAR#%v66%] >= 0 and [VAR#%v66%] <= 100
   TaskValueSet,[INT#61],[INT#62],[VAR#%v66%]
  else
   if [VAR#%v66%] <= 0
    Let,%v66%,0
    TaskValueSet,[INT#61],[INT#62],0
   else
    Let,%v66%,100
    TaskValueSet,[INT#61],[INT#62],100
   endif
  endif
 else
  if [VAR#%v66%] >= 0 and [VAR#%v66%] <= 100
   TaskValueSet,[INT#61],[INT#62],[VAR#%v66%]
  else
   if [VAR#%v66%] <= 0
    Let,%v66%,0
    TaskValueSet,[INT#61],[INT#62],0
   else
    Let,%v66%,100
    TaskValueSet,[INT#61],[INT#62],100
   endif
  endif
 endif
endon

//[VAR#33] seconds Z1L requested; [VAR#34] direction Z1L; [VAR#35] Z1L shutters percent
//[VAR#36] seconds Z1R requested; [VAR#37] direction Z1R; [VAR#38] Z1R shutters percent
//[VAR#12], [VAR#13], [VAR#14]: used temporary for calculations
//[VAR#1] to [VAR#10]: shutter event config
//TimerSet_ms,2 for locking and state ([Z1#M])

on Rules#Timer=2 do
 Let,60,18 // full open/close duration
 Let,61,2  // Taskvalue Device
 Let,62,2  // Taskvalue Variable
 Let,63,=[Z1#SL] // Current shutter state
 Let,64,33 // Timer Seconds requested VAR Number
 Let,65,34 // Timer shutter direction VAR Number
 Let,66,35 // Timer shutter percent VAR Number
 event,StateShutter
 Let,60,18 // full open/close duration
 Let,61,2  // Taskvalue Device
 Let,62,3  // Taskvalue Variable
 Let,63,=[Z1#SR] // Current shutter state
 Let,64,36 // Timer Seconds requested VAR Number
 Let,65,37 // Timer shutter direction VAR Number
 Let,66,38 // Timer shutter percent VAR Number
 event,StateShutter
 TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
 if [VAR#33] <= 0 and [VAR#36] <= 0
  TaskValueSet,2,4,0
  TimerSet_ms,2,0
 endif
 //SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=%sysname%&Z1=[Z1#M];[Z1#S];[Z1#SL];[Z1#SR];
endon

on ControlZ1 do
 //control?cmd=event,ControlZ1=0
 event,ControlZ1R=%eventvalue%
 event,ControlZ1L=%eventvalue%
endon

on ControlZ1L do
 Let,2,22 // GPIO 1
 Let,3,23 // GPIO 2
 Let,4,18 // full open/close duration
 Let,5,2  // Taskvalue Device and TimerIDX
 Let,6,2  // Taskvalue Variable
 Let,7,=[Z1#SL] // Current shutter state
 Let,8,33 // Timer Seconds requested VAR Number
 Let,9,34 // Timer shutter direction VAR Number
 Let,10,36 // timershared shutter VAR Number
 event,ControlShutter=%eventvalue%
endon

on ControlZ1R do
 Let,2,33 // GPIO 1
 Let,3,32 // GPIO 2
 Let,4,18 // full open/close duration
 Let,5,2  // Taskvalue Device and TimerIDX
 Let,6,3  // Taskvalue Variable
 Let,7,=[Z1#SR] // Current shutter state
 Let,8,36 // Timer Seconds requested VAR Number
 Let,9,37 // Timer shutter direction VAR Number
 Let,10,33 // timershared shutter VAR Number
 event,ControlShutter=%eventvalue%
endon

//[VAR#43] seconds Z2L requested; [VAR#44] direction Z2L; [VAR#45] Z2L shutters percent
//[VAR#46] seconds Z2R requested; [VAR#47] direction Z2R; [VAR#48] Z2R shutters percent
//[VAR#12], [VAR#13], [VAR#14]: used temporary for calculations
//[VAR#1] to [VAR#10]: shutter event config
//TimerSet_ms,3 for locking and state ([Z2#M])

on Rules#Timer=3 do
 Let,60,18 // full open/close duration
 Let,61,3  // Taskvalue Device
 Let,62,2  // Taskvalue Variable
 Let,63,=[Z2#SL] // Current shutter state
 Let,64,43 // Timer Seconds requested VAR Number
 Let,65,44 // Timer shutter direction VAR Number
 Let,66,45 // Timer shutter percent VAR Number
 event,StateShutter
 Let,60,18 // full open/close duration
 Let,61,3  // Taskvalue Device
 Let,62,3  // Taskvalue Variable
 Let,63,=[Z2#SR] // Current shutter state
 Let,64,46 // Timer Seconds requested VAR Number
 Let,65,47 // Timer shutter direction VAR Number
 Let,66,48 // Timer shutter percent VAR Number
 event,StateShutter
 TaskValueSet,3,1,(([Z2#SL]+[Z2#SR])/2)
 if [VAR#43] <= 0 and [VAR#46] <= 0
  TaskValueSet,3,4,0
  TimerSet_ms,3,0
 endif
 //SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=%sysname%&Z2=[Z2#M];[Z2#S];[Z2#SL];[Z2#SR];
endon

on ControlZ2 do
 //control?cmd=event,ControlZ2=0
 event,ControlZ2R=%eventvalue%
 event,ControlZ2L=%eventvalue%
endon

on ControlZ2L do
 Let,2,26 // GPIO 1
 Let,3,25 // GPIO 2
 Let,4,18 // full open/close duration
 Let,5,3  // Taskvalue Device and TimerIDX
 Let,6,2  // Taskvalue Variable
 Let,7,=[Z2#SL] // Current shutter state
 Let,8,43 // Timer Seconds requested VAR Number
 Let,9,44 // Timer shutter direction VAR Number
 Let,10,46 // timershared shutter VAR Number
 event,ControlShutter=%eventvalue%
endon

on ControlZ2R do
 Let,2,13 // GPIO 1
 Let,3,27 // GPIO 2
 Let,4,18 // full open/close duration
 Let,5,3  // Taskvalue Device and TimerIDX
 Let,6,3  // Taskvalue Variable
 Let,7,=[Z2#SR] // Current shutter state
 Let,8,46 // Timer Seconds requested VAR Number
 Let,9,47 // Timer shutter direction VAR Number
 Let,10,43 // timershared shutter VAR Number
 event,ControlShutter=%eventvalue%
endon

//[VAR#53] seconds Z3L requested; [VAR#54] direction Z3L; [VAR#55] Z3L shutters percent
//[VAR#56] seconds Z3R requested; [VAR#57] direction Z3R; [VAR#58] Z3R shutters percent
//[VAR#12], [VAR#13], [VAR#14]: used temporary for calculations
//[VAR#1] to [VAR#10]: shutter event config
//TimerSet_ms,4 for locking and state ([Z3#M])

on Rules#Timer=4 do
 Let,60,18 // full open/close duration
 Let,61,4  // Taskvalue Device
 Let,62,2  // Taskvalue Variable
 Let,63,=[Z3#SL] // Current shutter state
 Let,64,53 // Timer Seconds requested VAR Number
 Let,65,54 // Timer shutter direction VAR Number
 Let,66,55 // Timer shutter percent VAR Number
 event,StateShutter
 Let,60,18 // full open/close duration
 Let,61,4  // Taskvalue Device
 Let,62,3  // Taskvalue Variable
 Let,63,=[Z3#SR] // Current shutter state
 Let,64,56 // Timer Seconds requested VAR Number
 Let,65,57 // Timer shutter direction VAR Number
 Let,66,58 // Timer shutter percent VAR Number
 event,StateShutter
 TaskValueSet,4,1,(([Z3#SL]+[Z3#SR])/2)
 if [VAR#53] <= 0 and [VAR#56] <= 0
  TaskValueSet,4,4,0
  TimerSet_ms,4,0
 endif
 //SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=%sysname%&Z3=[Z3#M];[Z3#S];[Z3#SL];[Z3#SR];
endon

on ControlZ3 do
 //control?cmd=event,ControlZ3=0
 event,ControlZ3L=%eventvalue%
 event,ControlZ3R=%eventvalue%
endon

on ControlZ3L do
 Let,2,18 // GPIO 1
 Let,3,19 // GPIO 2
 Let,4,18 // full open/close duration
 Let,5,4  // Taskvalue Device and TimerIDX
 Let,6,2  // Taskvalue Variable
 Let,7,=[Z3#SL] // Current shutter state
 Let,8,53 // Timer Seconds requested VAR Number
 Let,9,54 // Timer shutter direction VAR Number
 Let,10,56 // timershared shutter VAR Number
 event,ControlShutter=%eventvalue%
endon

on ControlZ3R do
 Let,2,17 // GPIO 1
 Let,3,21 // GPIO 2
 Let,4,18 // full open/close duration
 Let,5,4  // Taskvalue Device and TimerIDX
 Let,6,3  // Taskvalue Variable
 Let,7,=[Z3#SR] // Current shutter state
 Let,8,56 // Timer Seconds requested VAR Number
 Let,9,57 // Timer shutter direction VAR Number
 Let,10,53 // timershared shutter VAR Number
 event,ControlShutter=%eventvalue%
endon

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#28 Post by TD-er » 10 Feb 2021, 14:58

First thing to look at is how often do you call Rules#timer=7 and =8 ?

Both call a SendToHTTP, which may take a while depending on the response time of the host.


Also you still have "delay" in the code which is blocking (in ControlShutter) which is called quite often and is quite long.
The timers you set are all set at roughly 1 second interval, but they all end up calling ControlShutter which does take at least 250 msec due to this delay.
For 4 blinds, the rules engine is continuously running behind on its schedule as 4 calls to ControlShutter every second already fill up the available time.

So my suggestion is to either find a way to get rid of this 250 msec delay, or set the loop timers to a longer interval.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#29 Post by _Cyber_ » 10 Feb 2021, 22:48

TD-er wrote: 10 Feb 2021, 14:58 First thing to look at is how often do you call Rules#timer=7 and =8 ?

Both call a SendToHTTP, which may take a while depending on the response time of the host.
Timer7 is only called once, currently.
Timer8 is set to the value to end in sync with the looptimer. so if I set the looptimer to 22 iterations, Timer8 will end after 22 seconds.
I already commented out the SendToHTTP, it did not help.
TD-er wrote: 10 Feb 2021, 14:58 Also you still have "delay" in the code which is blocking (in ControlShutter) which is called quite often and is quite long.
The timers you set are all set at roughly 1 second interval, but they all end up calling ControlShutter which does take at least 250 msec due to this delay.
For 4 blinds, the rules engine is continuously running behind on its schedule as 4 calls to ControlShutter every second already fill up the available time.

So my suggestion is to either find a way to get rid of this 250 msec delay, or set the loop timers to a longer interval.
The delay is only called once in Controlshutter, Controlshutter is repeated for each of the 7 shutters at the very beginning, the Looptimers are initialized after the delay.
I do not know how to handle a longer delay of the timers in code, as I LongPulse with seconds, I need the same amount of time for the timer. if I fire the timer only every three seconds, and the PongPulse was 5 seconds long, I would miss either 2 seconds or have one second too much. I have no idea how to circumvent this.

in the timers itself I only call the StateShutter event which has no delay - it calculates the difference per second and does the taskvalueset with the new value.

I calculated with excel timedifferences:
below the second column is the diff to the last entry, the third column it the diff between two LoopTimer_ms,1,1000 iterations.

Code: Select all

1192020	354	1088	EVENT:	Rules#Timer=1,5
1192104	84		ACT :	Let,60,28
1192108	4		ACT :	Let,61,1
1192112	4		ACT :	Let,62,2
1192153	41		ACT :	Let,63,=85.72
1192159	6		ACT :	Let,64,20
1192163	4		ACT :	Let,65,21
1192167	4		ACT :	Let,66,22
1192172	5		ACT :	event,StateShutter
1192174	2		EVENT:	StateShutter
1192429	255		ACT :	Let,20,10-1
1192436	7		ACT :	Let,11,-1
1192444	8		ACT :	Let,22,(85.7200012207031+(100/28)*-1)
1192507	63		ACT :	TaskValueSet,1,2,82.1485726492746
1192764	257		ACT :	TaskValueSet,1,1,82.15
1193120	356	1100	EVENT:	Rules#Timer=1,6
1193206	86		ACT :	Let,60,28
1193210	4		ACT :	Let,61,1
1193214	4		ACT :	Let,62,2
1193256	42		ACT :	Let,63,=82.15
1193262	6		ACT :	Let,64,20
1193267	5		ACT :	Let,65,21
1193271	4		ACT :	Let,66,22
1193276	5		ACT :	event,StateShutter
1193278	2		EVENT:	StateShutter
1193493	215		ACT :	Let,20,9-1
1193499	6		ACT :	Let,11,-1
1193507	8		ACT :	Let,22,(82.1500015258789+(100/28)*-1)
1193566	59		ACT :	TaskValueSet,1,2,78.5785729544503
1193816	250		ACT :	TaskValueSet,1,1,78.58
1194227	411	1107	EVENT:	Rules#Timer=1,7
so each 1000ms looptimer run needs 1100ms - any idea why?

also I saw: between the "EVENT: StateShutter" and the first action in the event there are always >200ms lost.

that brought me to the idea to move the StateShutter Event logic to the top of the rules1.txt.
and now, the difference:

Code: Select all

82951	313	1088	EVENT:	Rules#Timer=1,5
83092	141		ACT :	Let,60,28
83097	5		ACT :	Let,61,1
83101	4		ACT :	Let,62,2
83143	42		ACT :	Let,63,=85.72
83148	5		ACT :	Let,64,20
83152	4		ACT :	Let,65,21
83156	4		ACT :	Let,66,22
83161	5		ACT :	event,StateShutter
83163	2		EVENT:	StateShutter
83172	9		ACT :	Let,20,10-1
83178	6		ACT :	Let,11,-1
83186	8		ACT :	Let,22,(85.7200012207031+(100/28)*-1)
83249	63		ACT :	TaskValueSet,1,2,82.1485726492746
83703	454		ACT :	TaskValueSet,1,1,82.15
84009	306	1058	EVENT:	Rules#Timer=1,6
84122	113		ACT :	Let,60,28
84126	4		ACT :	Let,61,1
84130	4		ACT :	Let,62,2
84172	42		ACT :	Let,63,=82.15
84178	6		ACT :	Let,64,20
84182	4		ACT :	Let,65,21
84186	4		ACT :	Let,66,22
84190	4		ACT :	event,StateShutter
84192	2		EVENT:	StateShutter
84201	9		ACT :	Let,20,9-1
84208	7		ACT :	Let,11,-1
84217	9		ACT :	Let,22,(82.1500015258789+(100/28)*-1)
84333	116		ACT :	TaskValueSet,1,2,78.5785729544503
84796	463		ACT :	TaskValueSet,1,1,78.58
85108	312	1099	EVENT:	Rules#Timer=1,7
between "EVENT: StateShutter" and the first action in the event only 9ms are lost.
still the timer slips away by nearly 100ms - do you have an idea why?

So, I suspect each event the complete rules are parsed completely, there is no kind of "compile", or "offset where to find" for different events?

would it be faster if I make one big timer instead of 4 different one? I would need to if-check vars to select which calculation needs to be done, instead of letting the timer "preselect" this?
are rules1.txt to rules4.txt parsed all in one row?
will removing all spaces and comments speed the parsing up?
in the used functions, which are the "cheap" one like Let,..., and which are the "expensive" one? besides the http request (I will have a look if I can send by udp to another node which does the http request to my status host)

Thank you! :-)

Best regards
Alois

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#30 Post by TD-er » 10 Feb 2021, 23:16

The "extra" 100 msec for handling can be caused by a number of things.
The internal scheduler is a list of things to do at a specific time.
This list is sorted on the execution time.
So if you're running some blocking code for a few-100 msec, you know you delayed some other scheduled actions which are first in line to be executed.
For example the FIFTY_PER_SECOND, TEN_PER_SECOND and ONCE_PER_SECOND call are probably at the front of that list and they may take some time to be executed. Wouldn't be surprised if that would be in the order of 100 msec before the next event action is at the front of the scheduler list.

Parsing of the rules files does take some time and indeed parsing comments also takes time.
The files are read starting at 1 and continue in the order of the file numbers.
So it is best to place the most frequently occuring events at the beginning of file 1.
Maybe also add a dummy (empty) on...endon block for events that will be generated but not handled by you in the rules. (e.g. system clock, new values of your tasks, etc.)

Currently there is no cached info on what event blocks are present in the rules and their file/position.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#31 Post by _Cyber_ » 11 Feb 2021, 13:05

okay, I am despair of it. :-(
TD-er wrote: 10 Feb 2021, 23:16 Maybe also add a dummy (empty) on...endon block for events that will be generated but not handled by you in the rules. (e.g. system clock, new values of your tasks, etc.)
That's why I already set the Single event with all values: and set the Interval to 600 seconds.

but, besides this: I cannot get it working. :oops:
* I moved all to one timer and I am only driving one shutter.
* I made the event and the code now as compact as I can (if there are still ideas please tell me) the percent difference calculation now needs about 80ms.
* as soon as the calculation event ends, going back to the timer-code needs over 500ms, reproduceable always.
* parsing the rest of the timercode needs another 600ms
* sumed up the timer code needs about 1300ms to run

any ideas are welcome.

what I want to achieve: have the dummydevices at the percentage of the corresponding shutters.

I removed all comments and spaces, sadly now hard to read. put some "logentry" in to compare with the log.

Code: Select all

on StateShutter do
Let,%v64%,[INT#%v64%]-1
Let,11,[INT#%v65%]
Let,%v66%,([VAR#63]+(100/[INT#60])*[INT#11])
if [INT#%v64%] <= 0
Let,%v65%,0
if [VAR#%v66%] < 0
Let,%v66%,0
endif
if [VAR#%v66%] > 100
Let,%v66%,100
endif
else
if [VAR#%v66%] < 0
Let,%v66%,0
endif
if [VAR#%v66%] > 100
Let,%v66%,100
endif
endif
logentry,"endScalc"
endon

on Rules#Timer=5 do
if [INT#20] > 0
Let,60,28
Let,61,1
Let,62,2
Let,63,=[SZ#S1]
Let,64,20
Let,65,21
Let,66,22
event,StateShutter
TaskValueSet,1,2,[VAR#22]
TaskValueSet,1,1,[SZ#S1]
logentry,"endSZ"
endif
if [SZ#M] = 1 and [INT#20] = 0
TaskValueSet,1,4,0
Let,22,0
endif
if [INT#33] > 0
Let,60,18
Let,61,2
Let,62,2
Let,63,=[Z1#SL]
Let,64,33
Let,65,34
Let,66,35
event,StateShutter
TaskValueSet,2,2,[VAR#33]
TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
endif
if [INT#36] > 0
Let,60,18
Let,61,2
Let,62,3
Let,63,=[Z1#SR]
Let,64,36
Let,65,37
Let,66,38
event,StateShutter
TaskValueSet,2,3,[VAR#36]
TaskValueSet,2,1,(([Z1#SL]+[Z1#SR])/2)
logentry,"endZ1"
endif
if [Z1#M] = 1 and [INT#33] <= 0 and [INT#36] <= 0 and 
TaskValueSet,2,4,0
Let,35,0
Let,38,0
endif
if [INT#43] > 0
Let,60,18
Let,61,3
Let,62,2
Let,63,=[Z2#SL]
Let,64,43
Let,65,44
Let,66,45
event,StateShutter
TaskValueSet,3,2,[VAR#43]
TaskValueSet,3,1,(([Z2#SL]+[Z2#SR])/2)
endif
if [INT#46] > 0
Let,60,18
Let,61,3
Let,62,3
Let,63,=[Z2#SR]
Let,64,46
Let,65,47
Let,66,48
event,StateShutter
TaskValueSet,3,3,[VAR#46]
TaskValueSet,3,1,(([Z2#SL]+[Z2#SR])/2)
logentry,"endZ2"
endif
if [Z2#M] = 1 and [INT#43] <= 0 and [INT#46] <= 0
TaskValueSet,3,4,0
Let,45,0
Let,48,0
endif
if [INT#53] > 0
Let,60,18
Let,61,4
Let,62,2
Let,63,=[Z3#SL]
Let,64,53
Let,65,54
Let,66,55
event,StateShutter
TaskValueSet,4,2,[VAR#53]
TaskValueSet,4,1,(([Z3#SL]+[Z3#SR])/2)
endif
if [INT#56] > 0
Let,60,18
Let,61,4
Let,62,3
Let,63,=[Z3#SR]
Let,64,56
Let,65,57
Let,66,58
event,StateShutter
TaskValueSet,4,3,[VAR#56]
TaskValueSet,4,1,(([Z3#SL]+[Z3#SR])/2)
logentry,"endZ3"
endif
if [Z3#M] = 1 and [INT#53] <= 0 and [INT#56] <= 0
TaskValueSet,4,4,0
Let,55,0
Let,58,0
endif
logentry,"endT"
endon
again column 2 is the timediff to the previous act, column 3 is the diff to the previous started "Rules#Timer=5,x"

Code: Select all

919963			ACT :	Let,21,-1
919979	16		ACT :	loopTimerSet_ms,5,1000,14
920982	1003		EVENT:	Rules#Timer=5,1
921015	33		ACT :	Let,60,28
921019	4		ACT :	Let,61,1
921023	4		ACT :	Let,62,2
921055	32		ACT :	Let,63,=100.00
921061	6		ACT :	Let,64,20
921065	4		ACT :	Let,65,21
921068	3		ACT :	Let,66,22
921072	4		ACT :	event,StateShutter
921074	2		EVENT:	StateShutter
921083	9		ACT :	Let,20,14-1
921090	7		ACT :	Let,11,-1
921098	8		ACT :	Let,22,(100+(100/28)*-1)
921156	58		ACT :	logentry,'endScalc'
921157	1		endScalc	
921675	518		ACT :	TaskValueSet,1,2,96.4285714285714
921711	36		ACT :	TaskValueSet,1,1,96.43
921716	5		ACT :	logentry,'endSZ'
921718	2	736	endSZ	
922282	564		ACT :	logentry,'endT'
922284	2	1302	endT	
922713	429	1731	EVENT:	Rules#Timer=5,2
922746	33		ACT :	Let,60,28
922750	4		ACT :	Let,61,1
922754	4		ACT :	Let,62,2
922786	32		ACT :	Let,63,=96.43
922792	6		ACT :	Let,64,20
922796	4		ACT :	Let,65,21
922799	3		ACT :	Let,66,22
922803	4		ACT :	event,StateShutter
922805	2		EVENT:	StateShutter
922814	9		ACT :	Let,20,13-1
922821	7		ACT :	Let,11,-1
922829	8		ACT :	Let,22,(96.4300003051758+(100/28)*-1)
922879	50		ACT :	logentry,'endScalc'
922881	2		endScalc	
923384	503		ACT :	TaskValueSet,1,2,92.8585717337472
923421	37		ACT :	TaskValueSet,1,1,92.86
923426	5		ACT :	logentry,'endSZ'
923428	2	715	endSZ	
923981	553		ACT :	logentry,'endT'
923983	2	1270	endT	
924407	424	1694	EVENT:	Rules#Timer=5,3
924442	35		ACT :	Let,60,28
924446	4		ACT :	Let,61,1
924450	4		ACT :	Let,62,2
924482	32		ACT :	Let,63,=92.86
924488	6		ACT :	Let,64,20
924492	4		ACT :	Let,65,21
924495	3		ACT :	Let,66,22
924500	5		ACT :	event,StateShutter
924501	1		EVENT:	StateShutter
924510	9		ACT :	Let,20,12-1
924517	7		ACT :	Let,11,-1
924525	8		ACT :	Let,22,(92.8600006103516+(100/28)*-1)
924581	56		ACT :	logentry,'endScalc'
924583	2		endScalc	
925109	526		ACT :	TaskValueSet,1,2,89.288572038923
925145	36		ACT :	TaskValueSet,1,1,89.29
925151	6		ACT :	logentry,'endSZ'
925152	1	745	endSZ	
925720	568		ACT :	logentry,'endT'
925722	2	1315	endT	
926130	408	1723	EVENT:	Rules#Timer=5,4
926188	58		ACT :	Let,60,28
926194	6		ACT :	Let,61,1
926198	4		ACT :	Let,62,2
926230	32		ACT :	Let,63,=89.29
926236	6		ACT :	Let,64,20
926240	4		ACT :	Let,65,21
926244	4		ACT :	Let,66,22
926248	4		ACT :	event,StateShutter
926250	2		EVENT:	StateShutter
926258	8		ACT :	Let,20,11-1
926265	7		ACT :	Let,11,-1
926273	8		ACT :	Let,22,(89.2900009155274+(100/28)*-1)
926330	57		ACT :	logentry,'endScalc'
926332	2		endScalc	
926835	503		ACT :	TaskValueSet,1,2,85.7185723440988
926871	36		ACT :	TaskValueSet,1,1,85.72
926877	6		ACT :	logentry,'endSZ'
926878	1		endSZ	
927443	565		ACT :	logentry,'endT'
927444	1		endT	
927842	398	1712	EVENT:	Rules#Timer=5,5
927875	33		ACT :	Let,60,28
927879	4		ACT :	Let,61,1
927882	3		ACT :	Let,62,2
927914	32		ACT :	Let,63,=85.72
927920	6		ACT :	Let,64,20
927923	3		ACT :	Let,65,21
927927	4		ACT :	Let,66,22
927931	4		ACT :	event,StateShutter
927933	2		EVENT:	StateShutter
927942	9		ACT :	Let,20,10-1
927949	7		ACT :	Let,11,-1
927957	8		ACT :	Let,22,(85.7200012207031+(100/28)*-1)
928016	59		ACT :	logentry,'endScalc'
928018	2		endScalc	
928577	559		ACT :	TaskValueSet,1,2,82.1485726492746
928613	36		ACT :	TaskValueSet,1,1,82.15
928619	6		ACT :	logentry,'endSZ'
928620	1		endSZ	
929193	573		ACT :	logentry,'endT'
929195	2		endT	
929598	403	1756	EVENT:	Rules#Timer=5,6
929633	35		ACT :	Let,60,28
929637	4		ACT :	Let,61,1
929641	4		ACT :	Let,62,2
929673	32		ACT :	Let,63,=82.15
929679	6		ACT :	Let,64,20
929683	4		ACT :	Let,65,21
929687	4		ACT :	Let,66,22
929691	4		ACT :	event,StateShutter
929693	2		EVENT:	StateShutter
929701	8		ACT :	Let,20,9-1
929708	7		ACT :	Let,11,-1
929716	8		ACT :	Let,22,(82.1500015258789+(100/28)*-1)
929772	56		ACT :	logentry,'endScalc'
929774	2		endScalc	
930340	566		ACT :	TaskValueSet,1,2,78.5785729544503
930377	37		ACT :	TaskValueSet,1,1,78.58
930383	6		ACT :	logentry,'endSZ'
930384	1		endSZ	
930935	551		ACT :	logentry,'endT'
930937	2		endT	
931365	428	1767	EVENT:	Rules#Timer=5,7
931399	34		ACT :	Let,60,28
931403	4		ACT :	Let,61,1
931406	3		ACT :	Let,62,2
931438	32		ACT :	Let,63,=78.58
931444	6		ACT :	Let,64,20
931447	3		ACT :	Let,65,21
931451	4		ACT :	Let,66,22
931455	4		ACT :	event,StateShutter
931457	2		EVENT:	StateShutter
931466	9		ACT :	Let,20,8-1
931473	7		ACT :	Let,11,-1
931481	8		ACT :	Let,22,(78.5800018310547+(100/28)*-1)
931539	58		ACT :	logentry,'endScalc'
931541	2		endScalc	
932062	521		ACT :	TaskValueSet,1,2,75.0085732596261
932098	36		ACT :	TaskValueSet,1,1,75.01
932103	5		ACT :	logentry,'endSZ'
932105	2		endSZ	
932661	556		ACT :	logentry,'endT'
932663	2		endT	
933080	417	1715	EVENT:	Rules#Timer=5,8
933113	33		ACT :	Let,60,28
933117	4		ACT :	Let,61,1
933121	4		ACT :	Let,62,2
933154	33		ACT :	Let,63,=75.01
933159	5		ACT :	Let,64,20
933163	4		ACT :	Let,65,21
933167	4		ACT :	Let,66,22
933171	4		ACT :	event,StateShutter
933173	2		EVENT:	StateShutter
933181	8		ACT :	Let,20,7-1
933187	6		ACT :	Let,11,-1
933194	7		ACT :	Let,22,(75.0100021362305+(100/28)*-1)
933246	52		ACT :	logentry,'endScalc'
933247	1		endScalc	
933764	517		ACT :	TaskValueSet,1,2,71.4385735648019
933800	36		ACT :	TaskValueSet,1,1,71.44
933805	5		ACT :	logentry,'endSZ'
933807	2		endSZ	
934360	553		ACT :	logentry,'endT'
934361	1		endT	

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#32 Post by TD-er » 11 Feb 2021, 13:14

Without trying to decrypt your rules.
What are the steps needed for your blinds?
Maybe we can come up with a way easier method as it should not be this university grade kind of rules set.

So please enumerate the steps in normal English what should be done and if needed mention some fixed intervals too.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#33 Post by _Cyber_ » 11 Feb 2021, 13:45

drive down:
enable overall power (GPIO2 to 0)
Pulse one GPIO (4) to 0 for specific seconds
keep one other GPIO (16) to 1
--> keep track of the seconds which it is pulsed and update (secondly, two-secondly) a HTTP host with the state in percent (if it delays too much update another ESPeasy host with UDP which does the HTTP update instead)
possibility to stop (and know afterwards how much % are driven)
disable overall power (GPIO2 to 1)

drive up:
enable overall power (GPIO2 to 0)
Pulse one GPIO (4) to 0 for specific seconds
Pulse other GPIO (16) to 0 for same specific seconds
--> keep track of the seconds which it is pulsed and update (secondly, two-secondly) a HTTP host with the state in percent (if it delays too much update another ESPeasy host with UDP which does the HTTP update instead)
possibility to stop (and know afterwards how much % are driven)
disable overall power (GPIO2 to 1)

stop:
pulsed GPIO to "1"
disable overall power (GPIO2 to 1)

important: as the shutter motors die if they get instantly triggered from the one to the other direction they need to be "paused" anyhow between by minimum 250ms.

this is already done all and working in event ControlShutter - except the percentage tracking

the 7 shutters are in 4 rooms, 3 rooms have always a pairs of them with 18 seconds close/open time, 1 room has one shutter with 28 seconds close/open time.
all shutters share the same "power"-GPIO2.

there should be a room control (close / open both shutters in parallel) while also a single control should be available.

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#34 Post by TD-er » 11 Feb 2021, 14:13

I think the rules can be a lot less complex if you have an event when a longpulse (or longpulse_ms) ends.

I am not really sure about the usefullness of the position detection, as DC motors never run always at the same speed.
So over time you will loose track of the position.

The rules should be considered a state machine, which doesn't have to be that complex.

State values:
  • Sleep
  • Power enabled (GPIO-2 to 0)
  • Start longpulse (GPIO-4)
  • Stop longpulse (GPIO-4)
  • GPIO-16 to 1 + log start time
  • Drive down running
  • Stop => disable power (GPIO-2 to 1)
This state can be checked very easy in the rules like this:

Code: Select all

if state = 1 

elseif state = 2

elseif state = 3

endif
You can already get an event when the longpulse ends by simply starting to monitor the GPIO pin right after you call longpulse and stop monitoring (unmonitor) if you receive the event (and were expecting it)

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#35 Post by _Cyber_ » 12 Feb 2021, 17:47

the losing track issue over time is corrected with the complete time for open or close action. there I do not drive only the difference, i always pulse the whole time to ensure it is closed / open completely. as at least one day a time it is closed completely it should not be noticeable, except the childs start playing with the shutters :D

I have tried with monitoring the GPIO. altough I have moved the monitor event to the top in the rules, it is called / executed (with no background tasks on the esp this time, so no load) between 500ms and 1500ms later, after the pulse ends. I calculated the timedifferece with syssec_d, with its granularity I have 14secs pulse time and 16secs logged time. so this seems also to be not an option.

I am trying now sending the variables (seconds and direction) in a secondly timer to the webserver which then does the percent-calculation. currently it looks promising as the timer is "in time", but have not done all shutters so far.

in your suggestion I could extract the information that a "elseif" exists. I did not know that, have already reworked some workarounds caused by this.

https://espeasy.readthedocs.io/en/lates ... tml#and-or here is a note, that "up to three" values can be in the statement. I have some if's which have more, but they seem working. is this limitation still true?

Thanks. :-)

BR
Alois

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#36 Post by TD-er » 12 Feb 2021, 22:18

I don't think this is a hard limit anymore, but I am not sure what may be the limit here.
It has been quite a while since I changed the code to perform a while loop in processing it.
I guess it may have some limit like 9 or 10 so we don't continue forever on bogus rules.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#37 Post by _Cyber_ » 15 Feb 2021, 21:38

ok, I am now nearly there wehere I would like to be.
I am keeping track with syssec_d when I start the timer. with this, I calculate the real time difference, not relying any more on timers called in time.
especially the event queue seem to delay timers heavily.

now three (hopefully last) question:
a) is there any (system)-variable which I can use for in milliseconds resolution? I can see this great uptime-millis, is'nt there a way to get them as variable in rules?
not because I want to calculate in milliseconds :D , because with seconds granularity there is rounding - which is never avoidable, but makes a difference if it is in seconds or ms.

b) is there a way to get the start of a timer as a variable? so e.g. looptimer3 start, it is currently at iteration 8 but already 13445msecs are gone since the start. best also to have the same unit (unixtime_ms, syssec_d_ms, or uptime_ms) to avoid another calculation. ;)

c) maybe splitting up of the events and timerevents will be considered?
as everything needs to be handled with events, a single eventqueue will always delay timerevents, which should be (at least with the _ms extension) more or less precise. this is regrettably currently not the case.

Thanks!

BR
Alois

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#38 Post by TD-er » 15 Feb 2021, 21:49

Those are not yet present, but Grovkillen is also asking me for a while to have the %uptime_ms%, which is essentially millis().
So that will be added soon.

The others are also feasible, but I don't know if unixtime_ms is also usable to keep in sync with other nodes as NTP does have a jitter of +/- 30 msec among nodes.
For the ESPEasyNOW feature I'm working on you can have a shorter jitter, but still the drift of a single node may be significant over the day due to quality variation of the crystal oscillators used.

Thus measuring intervals on the same node would be useful, but keeping nodes in sync at msec level is not there yet (but working on it :) )

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#39 Post by _Cyber_ » 16 Feb 2021, 17:49

I noticed, this node got quite unstable, has a uptime of 10mins up to 2 hours, but not more. It is doing nothing, besides one HTTP call a minute (the rule is in rules1.txt at the very front, it is the 3rd on / endon block, 1882 chars are before it). the load is normally below 15%

Code: Select all

on Clock#Time=All,**:** do
 SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=%sysname%&ipv4=%ip%&uptime=%uptime%&load=%sysload%&freeram=%sysheap%&rssi=%rssi%&SZ=[SZ#M];[SZ#S];&Z1=[Z1#M];[Z1#S];[Z1#SL];[Z1#SR];&Z2=[Z2#M];[Z2#S];[Z2#SL];[Z2#SR];&Z3=[Z3#M];[Z3#S];[Z3#SL];[Z3#SR];
endon
Last Action before Reboot: Background Task
running ESP_Easy_mega_20210114_normal_ESP32_4M316k

I captured on serial port, see below.

any ideas what's causing this?

Code: Select all

5882425 : Info   : EVENT: Clock#Time=Tue,17:36
5882458 : Debug  : ReplacementString SunTime: %sunset% offset: 0
5882549 : Info   : ACT  : SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=RolloBackup&ipv4=192.168.10.122&uptime=98&load=14.55&freeram=204076&rssi=-89&SZ=0;100.00;&Z1=0;100.00;100.00;100.00;&Z2=0;100.00;100.00;100.00;&Z3=0;100.00;100.00;100.00;
5882555 : Debug  : Command: SendToHTTP
5882555 : Debug  : SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=RolloBackup&ipv4=192.168.10.122&uptime=98&load=14.55&freeram=204076&rssi=-89&SZ=0;100.00;&Z1=0;100.00;100.00;100.00;&Z2=0;100.00;100.00;100.00;&Z3=0;100.00;100.00;100.00;
5882556 : Debug  : Par1: 192 Par2: 80 Par3: 80 Par4: 0 Par5: 0
5882557 : Debug  : SendToHTTP: Host: 192.168.0.250 port: 80
5882557 : Debug  : SendToHTTP: Path: /apcucollector.php?smartswitch=RolloBackup&ipv4=192.168.10.122&uptime=98&load=14.55&freeram=204076&rssi=-89&SZ=0;100.00;&Z1=0;100.00;100.00;100.00;&Z2=0;100.00;100.00;100.00;&Z3=0;100.00;100.00;100.00;
5882570 : Debug  : GET /apcucollector.php?smartswitch=RolloBackup&ipv4=192.168.10.122&uptime=98&load=14.55&freeram=204076&rssi=-89&SZ=0;100.00;&Z1=0;100.00;100.00;100.00;&Z2=0;100.00;100.00;100.00;&Z3=0;100.00;100.00;100.00; HTTP/1.1
Host: 192.168.0.250
Accept: */*;q=0.1
User-Agent: ESP Easy/20111/Jan 14 2021 23:28:13
Connection: close


5882570 : Debug  : GET /apcucollector.php?smartswitch=RolloBackup&ipv4=192.168.10.122&uptime=98&load=14.55&freeram=204076&rssi=-89&SZ=0;100.00;&Z1=0;100.00;100.00;100.00;&Z2=0;100.00;100.00;100.00;&Z3=0;100.00;100.00;100.00; HTTP/1.1
Host: 192.168.0.250
Accept: */*;q=0.1
User-Agent: ESP Easy/20111/Jan 14 2021 23:28:13
Connection: close


5882572 : Debug  : HTTP : Command_HTTP_SendToHTTP written to client (70/326)
5882572 : Debug  : HTTP : Command_HTTP_SendToHTTP closing connection
5882827 : Debug  : EVENT: Clock#Time=Tue,17:36 Processing time:402 milliSeconds
5884979 : Info   : WD   : Uptime 98 ConnectFailures 0 FreeMem 204816 WiFiStatus WL_CONNECTED ESPeasy internal wifi status: Conn. IP Init
5885868 : Debug  : LoopStats: shortestLoop: 584 longestLoop: 1109157 avgLoopDuration: 711.85 loopCounterMax: 51369 loopCounterLast: 42061
5885869 : Debug  : Scheduler stats: (called/tasks/max_length/idle%) 42061/2103/10/84.29
5914979 : Info   : WD   : Uptime 99 ConnectFailures 0 FreeMem 204828 WiFiStatus WL_CONNECTED ESPeasy internal wifi status: Conn. IP Init
5915868 : Debug  : LoopStats: shortestLoop: 584 longestLoop: 1109157 avgLoopDuration: 702.30 loopCounterMax: 51369 loopCounterLast: 42633
5915869 : Debug  : Scheduler stats: (called/tasks/max_length/idle%) 42633/2132/10/85.44
5942425 : Info   : EVENT: Clock#Time=Tue,17:37
5942458 : Debug  : ReplacementString SunTime: %sunset% offset: 0
5942549 : Info   : ACT  : SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=RolloBackup&ipv4=192.168.10.122&uptime=99&load=14.56&freeram=204080&rssi=-89&SZ=0;100.00;&Z1=0;100.00;100.00;100.00;&Z2=0;100.00;100.00;100.00;&Z3=0;100.00;100.00;100.00;
5942554 : Debug  : Command: SendToHTTP
5942555 : Debug  : SendToHTTP,192.168.0.250,80,/apcucollector.php?smartswitch=RolloBackup&ipv4=192.168.10.122&uptime=99&load=14.56&freeram=204080&rssi=-89&SZ=0;100.00;&Z1=0;100.00;100.00;100.00;&Z2=0;100.00;100.00;100.00;&Z3=0;100.00;100.00;100.00;
5942555 : Debug  : Par1: 192 Par2: 80 Par3: 80 Par4: 0 Par5: 0
5942556 : Debug  : SendToHTTP: Host: 192.168.0.250 port: 80
5942557 : Debug  : SendToHTTP: Path: /apcucollector.php?smartswitch=RolloBackup&ipv4=192.168.10.122&uptime=99&load=14.56&freeram=204080&rssi=-89&SZ=0;100.00;&Z1=0;100.00;100.00;100.00;&Z2=0;100.00;100.00;100.00;&Z3=0;100.00;100.00;100.00;
5942567 : Debug  : GET /apcucollector.php?smartswitch=RolloBackup&ipv4=192.168.10.122&uptime=99&load=14.56&freeram=204080&rssi=-89&SZ=0;100.00;&Z1=0;100.00;100.00;100.00;&Z2=0;100.00;100.00;100.00;&Z3=0;100.00;100.00;100.00; HTTP/1.1
Host: 192.168.0.250
Accept: */*;q=0.1
User-Agent: ESP Easy/20111/Jan 14 2021 23:28:13
Connection: close


5942568 : Debug  : GET /apcucollector.php?smartswitch=RolloBackup&ipv4=192.168.10.122&uptime=99&load=14.56&freeram=204080&rssi=-89&SZ=0;100.00;&Z1=0;100.00;100.00;100.00;&Z2=0;100.00;100.00;100.00;&Z3=0;100.00;100.00;100.00; HTTP/1.1
Host: 192.168.0.250
Accept: */*;q=0.1
User-Agent: ESP Easy/20111/Jan 14 2021 23:28:13
Connection: close


5942570 : Debug  : HTTP : Command_HTTP_SendToHTTP written to client (70/326)
5942570 : Debug  : HTTP : Command_HTTP_SendToHTTP closing connection
5942824 : Debug  : EVENT: Clock#Time=Tue,17:37 Processing time:399 milliSeconds
5944979 : Info   : WD   : Uptime 99 ConnectFailures 0 FreeMem 204820 WiFiStatus WL_CONNECTED ESPeasy internal wifi status: Conn. IGuru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump:
PC      : 0x401f067d  PS      : 0x00060630  A0      : 0x801200d1  A1      : 0x3ffb1f10  
A2      : 0x3ffd9d38  A3      : 0x3ffc2ab0  A4      : 0x3ffc24fc  A5      : 0x62593db6  
A6      : 0x0000002f  A7      : 0x3ffc15a4  A8      : 0xffffff9f  A9      : 0x3ffd9cd7  
A10     : 0x3ffb40cc  A11     : 0x000000da  A12     : 0x05908a37  A13     : 0x00000000  
A14     : 0x0000007a  A15     : 0x3ffd8140  SAR     : 0x00000008  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x801200d1  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  

Backtrace: 0x401f067d:0x3ffb1f10 0x401200ce:0x3ffb1f30 0x401004b8:0x3ffb1f50 0x40100660:0x3ffb1f80 0x40169cc4:0x3ffb1fb0 0x40089fc5:0x3ffb1fd0

Rebooting...

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#40 Post by TD-er » 16 Feb 2021, 19:47

Hmm that looks a bit like trying to use a flash string where a normal char pointer is expected, or trying to access some data which already has been destructed.
-> Programming error.

Is it always at the same log entry?
Does it run more stable with all logs disabled? (to check if it is somewhere in the logs)

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#41 Post by _Cyber_ » 17 Feb 2021, 08:21

normally I have disabled the debuglog, and also serial console is disabled completely. so I noticed the reboots also with only "Web Log Level" set to "Info", but no client was fetching the weblogs, I assume then it is not generated?
the issue with the serial console is, that the ESP32 is quite ugly to attach a putty to it. It resets immediately after boot as soon as I have a serial client on it, I read something about Flow Control, tried to disable, but it still is nearly impossible to have a serial client capturing it. yesterday I succeeded after trying half an hour, then it was runnin until the crash from above.

now again it was running, but only 10secs until it died with:

Code: Select all

7030 : Debug  : ReplacementString SunTime: %sunset% offset: 0
7273 : Debug  : EVENT: SZ#All=-1.00,0.00,0.00,0 Processing time:277 milliSeconds
7282 : Info   : EVENT: Z1#All=-1.00,0.00,0.00,0
7313 : Debug  : ReplacementString SunTime: %sunset% offset: 0
7544 : Debug  : EVENT: Z1#All=-1.00,0.00,0.00,0 Processing time:262 milliSeconds
7550 : Info   : EVENT: Z2#All=-1.00,0.00,0.00,0
7582 : Debug  : ReplacementString SunTime: %sunset% offset: 0
7815 : Debug  : EVENT: Z2#All=-1.00,0.00,0.00,0 Processing time:264 milliSeconds
7822 : Info   : EVENT: Z3#All=-1.00,0.00,0.00,0
7853 : Debug  : ReplacementString SunTime: %sunset% offset: 0
8084 : Debug  : EVENT: Z3#All=-1.00,0.00,0.00,0 Processing time:262 milliSeconds
8092 : Info   : EVENT: WiFi#ChangedAccesspoint
8124 : Debug  : ReplacementString SunTime: %sunset% offset: 0
8350 : Debug  : EVENT: WiFi#ChangedAccesspoint Processing time:258 milliSeconds
8359 : Info   : EVENT: WiFi#ChangedWiFichannel
8391 : Debug  : ReplacementString SunTime: %sunset% offset: 0
8616 : Debug  : EVENT: WiFi#ChangedWiFichannel Processing time:257 milliSeconds
8624 : Info   : EVENT: WiFi#Connected
8655 : Debug  : ReplacementString SunTime: %sunset% offset: 0
8883 : Debug  : EVENT: WiFi#Connected Processing time:259 milliSeconds
8890 : Info   : EVENT: Time#Initialized
8922 : Debug  : ReplacementString SunTime: %sunset% offset: 0
9148 : Debug  : EVENT: Time#Initialized Processing time:258 milliSeconds
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.
Core 0 register dump:
PC      : 0x401d2e96  PS      : 0x00060530  A0      : 0x801c8ea5  A1      : 0x3ffafc10
A2      : 0x3ffcac64  A3      : 0x3ffb4178  A4      : 0x00000001  A5      : 0x00000001
A6      : 0x00060b20  A7      : 0x00000000  A8      : 0x801c6fea  A9      : 0x3ffafbf0
A10     : 0x3ffb4178  A11     : 0x00060b23  A12     : 0x00060b20  A13     : 0x00000001
A14     : 0x00060b23  A15     : 0x00000000  SAR     : 0x00000019  EXCCAUSE: 0x0000001c
EXCVADDR: 0x801c8ea5  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff

Backtrace: 0x401d2e96:0x3ffafc10 0x401c8ea2:0x3ffafc30 0x401c8d25:0x3ffafc50 0x401c8ee0:0x3ffafc70 0x401c1a88:0x3ffafc90 0x40089fc5:0x3ffafcc0

Rebooting...
or the next:

Code: Select all

3872 : Info   : Dummy: value 2: 0.00
3873 : Info   : Dummy: value 3: 0.00
3875 : Info   : Dummy: value 4: 0
3925 : Info   : Dummy: value 1: -1.00
3927 : Info   : Dummy: value 2: 0.00
3928 : Info   : Dummy: value 3: 0.00
3930 : Info   : Dummy: value 4: 0
3993 : Info   : EVENT: TaskInit#SZ=1,0
4720 : Info   : EVENT: TaskInit#Z1=2,0
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump:
PC      : 0x401004c9  PS      : 0x00060630  A0      : 0x8011cc54  A1      : 0x3ffb1d30
A2      : 0x3ffc2248  A3      : 0x3ffc31e6  A4      : 0x004bc1f4  A5      : 0x00000000
A6      : 0x3ffb1d9f  A7      : 0x3ffb1da0  A8      : 0x801004c6  A9      : 0x3ffb1d00
A10     : 0x623fe993  A11     : 0x623fe993  A12     : 0x3ffc4f08  A13     : 0x3ffc4ac8
A14     : 0x00000065  A15     : 0xff000000  SAR     : 0x00000010  EXCCAUSE: 0x0000001c
EXCVADDR: 0x8011cd14  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff

Backtrace: 0x401004c9:0x3ffb1d30 0x4011cc51:0x3ffb1d60 0x4011cf25:0x3ffb1e30 0x4011d193:0x3ffb1eb0 0x401300e0:0x3ffb1ee0 0x40132024:0x3ffb1f20 0x40132a86:0x3ffb1f40 0x4010065a:0x3ffb1f80 0x40169cc4:0x3ffb1fb0 0x40089fc5:0x3ffb1fd0

Rebooting...
or the next:

Code: Select all

9060 : Debug  : LoopStats: shortestLoop: 16967 longestLoop: 2354066 avgLoopDuration: 234278.30 loopCounterMax: 1768 loopCounterLast: 22
9061 : Debug  : Scheduler stats: (called/tasks/max_length/idle%) 17/17/10/0.00
9118 : Info   : EVENT: SZ#All=-1.00,0.00,0.00,0
9189 : Debug  : ReplacementString SunTime: %sunset% offset: 0
ÁÑ¥½¹ÂWÖ.¤]tion Error: Core  1 panic'ed (IllegalInstruction).*
           +«v¸5RjUµ½Éå"ÕµÁ
                           ÑÂÑ¢2ÁÒÂÁͲ
                                       Ūª²j¤4êKW¤&H®YV­.]Y¹dump:
PC      : 0x401004f4  PS      : 0x00060230  A0      : 0x8011cc54  A1      : 0x3ffb1d30
A2      : 0x3ffc2248  A3      : 0x00000038  A4      : 0x009a987b  A5      : 0x00000000
A6      : 0x3ffb1d9f  A7      : 0x3ffb1da0  A8      : 0x801004dd  A9      : 0x3ffb1c70
A10     : 0xb4f0e2b8  A11     : 0xb4f0e2b8  A12     : 0x3ffc4f08  A13     : 0x00000000
A14     : 0x00000069  A15     : 0xff000000  SAR     : 0x00000010  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff

Backtrace: 0x401004f4:0x3ffb1d30 0x4011cc51:0x3ffb1d60 0x4011cf25:0x3ffb1e30 0x4011d193:0x3ffb1eb0 0x401300e0:0x3ffb1ee0 0x40132024:0x3ffb1f20 0x40132a86:0x3ffb1f40 0x4010065a:0x3ffb1f80 0x40169cc4:0x3ffb1fb0 0x40089fc5:0x3ffb1fd0

Rebooting...
but most likely it dies already at network scan:

Code: Select all

907 : Info   : WIFI : Set WiFi to STA
1101 : Info  àø~Î8àx<$HHStart network scan
3011 : Info   : WIFàÀàð
                       þþ¼ð¾Y,]Z·¤)[Z·+TJTJUê
                                             RWV
                                                ¤¤LC
&LL&H'HR·³o   : WIFI  : Arduino wifi status: WL_DISCONNECTED ESPeasy internal wifi status: DISCONNECTED
3017 : Info   : Webserver: start
3017 : Info   : WIFI : Starting mDNS...
3018 : Info   : WIFI : mDNS started, with name: RolloBackup.local
3023 : Info   : OTA  : Arduino OTA enabled on port 3232
3036 : Info   : EVENT: System#Boot
ààðàààðð<üðð0Îpø8çitation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40198d8c: 08e0c46f ad228f00 22042803
Core 0 register dump:
PC      : 0x40198d91  PS      : 0x00060f30  A0      : 0x8016e2f5  A1      : 0x3ffb78d0
A2      : 0x00000000  A3      : 0x3ffd66d8  A4      : 0x3ffbfac8  A5      : 0x00000001
A6      : 0x00060b20  A7      : 0x00000000  A8      : 0x80198d91  A9      : 0x3ffb7890
A10     : 0x00000000  A11     : 0x3ffd66d8  A12     : 0x0000000a  A13     : 0x4016c588
A14     : 0x3ffbaedc  A15     : 0x00000000  SAR     : 0x00000000  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff

Backtrace: 0x40198d91:0x3ffb78d0 0x4016e2f2:0x3ffb78f0 0x4016e367:0x3ffb7910 0x40089fc5:0x3ffb7930

Rebooting...
//Edit: ok, managed to get it on serial console running again. set web loglevel to "None" and serial loglevel to "Info" - lets look how long it lasts

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#42 Post by TD-er » 17 Feb 2021, 08:44

I assume you're powering it via USB?
Can you try another USB cable, another USB port (preferrably USB3 on a computer, not a hub) or maybe power it directly on the pins of the ESP32?
I do have several ESP32's here running for weeks and also some with the latest code running stable for days.

The reason your unit reboots when connecting a serial client is probably because your unit uses a CP2102 USB to uart chip (the small square one)
Units using this chip always reboot when you open a connection to it.
But as long as you have the connection open, you will even capture pre-boot texts if you like.

Personally I do like those CP2102 more than the CH340 as they seem to be more reliable on higher baud rates.
The CH340 have caused my USB hubs to need a reboot every now and then, which I never have seen with those CP2102 units. Sometimes even need a reboot of Windows to get USB to recognize any USB device again. (Using expensive Anker powered USB3 hubs here, so not a no-brand China device)

The web-log level is indeed dynamic based on whether it has been fetched in the last N seconds. You can see on the sysinfo page the actual loglevel state.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#43 Post by _Cyber_ » 17 Feb 2021, 09:06

I powered over the integrated USB-Port (over the CP2102) and as I read about the reset on plugging in the serial line and I could not cut TX line between CP2102 chip and ESP I am now powering over 3.3V pins + FTDI USB2Serial converter. but even there it resetted (the logs above are all with the FTDI converter) only the whole time.

I now figured out, maybe a working serial is only possible after letting the ESP boot and put afterwards the (FTDI)RX-TX(ESP32pin) onto the pin. thats how I could now attach it now without reboot (will not try if this is reproduceable as I want to fetch now another crash ;) )

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#44 Post by TD-er » 17 Feb 2021, 09:18

The reason it reboots when initiating a connection is due to the fact the RTS/CTS pins (or DTR, always forget which) are connected via 2 transistors to reset and GPIO-0.
This will put the ESP in flash mode when flashing.
But on the CP2102 it does trigger a reset when opening a connection.

So there's not much you can do to it, other then just leaving the connection open.

What plugins are you using?
What controllers?
What other non-standard settings do you use? (send to log server has been mentioned by some in the past as cause for reboot for example)

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#45 Post by _Cyber_ » 04 Apr 2021, 17:58

by the way: during looking for the reason the issue has gone away, without any specific idea what was causing... :roll:

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#46 Post by _Cyber_ » 06 Apr 2021, 14:40

TD-er wrote: 15 Feb 2021, 21:49 Those are not yet present, but Grovkillen is also asking me for a while to have the %uptime_ms%, which is essentially millis().
So that will be added soon.

The others are also feasible, but I don't know if unixtime_ms is also usable to keep in sync with other nodes as NTP does have a jitter of +/- 30 msec among nodes.
For the ESPEasyNOW feature I'm working on you can have a shorter jitter, but still the drift of a single node may be significant over the day due to quality variation of the crystal oscillators used.

Thus measuring intervals on the same node would be useful, but keeping nodes in sync at msec level is not there yet (but working on it :) )
@TD-er can you tell me if %uptime_ms% or something similar in ms is available in the meantime?

Thank you. :-)

BR
Alois

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: ESP32 resets on rules processing

#47 Post by TD-er » 06 Apr 2021, 14:46

Not yet. Jimmy is also asking me for it, so I will add it to access the "millis()' function.

_Cyber_
Normal user
Posts: 113
Joined: 20 Oct 2019, 09:46

Re: ESP32 resets on rules processing

#48 Post by _Cyber_ » 06 Apr 2021, 15:13

thank you. :-)
the "winter"-project for the shutters was quite successful, so the legacy buttons on the wall are very very rarely used. :D
now the "summer" part wants to start where I control them based on outside temperature. means, some more lines in the in sum over 14k long ruleset :shock:
still hoping to get be a bit more performance in future, until then the millis() function should be able to do the difference calculation. ;)

BR
Alois

Post Reply

Who is online

Users browsing this forum: Google [Bot] and 28 guests