Cron P081 is looping (sometimes)

Moderators: grovkillen, Stuntteam, TD-er

Post Reply
Message
Author
lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Cron P081 is looping (sometimes)

#1 Post by lollypop » 07 Dec 2022, 09:13

Hi Easiers,

I have a problem with cron (P081) in a Collection A build (ESP_Easy_mega_20221105_collection_A_ESP8266_4M1M, but same with ESP_Easy_mega_20220809_collection_A_ESP8266_4M1M).
My hardware is a "Espressif Generic ESP8266 ESPEasy 4M Flash 1M FS" with 4 relays on it (ESP12F_Relay_X4).

I created
- a Generic - MQTT Import device

Code: Select all

Name: MQTT
MQTT Topic <n>: Relay<n>
Value <n>: Value_of_Relay<n>
- a Generic - CRON named Relay4 with the following espression:

Code: Select all

0 42 6,10,15,16 * * *
- rules like this:

Code: Select all

on MQTT#Relay* do
  let,1,15                               // Relay 1 is GPIO15
  let,2,14                               // Relay 2 is GPIO14
  let,3,12                               // Relay 3 is GPIO12
  let,4,13                               // Relay 4 is GPIO13
  if %eventvalue1%<0                   
    //
    // Values below 0 sets timer to %eventvalue1%*-1 seconds
    //
    let,5,abs(%eventvalue1%)
    logentry,"%eventname%: Turn on {substring:5:11:%eventname%} (GPIO%v{substring:10:11:%eventname%}%) for %v5% seconds."
    timerSet,{substring:10:11:%eventname%},%v5%
    gpio,%v{substring:10:11:%eventname%}%,1
  elseif %eventvalue1%=1
    //
    // Value equal 1 turn on relay
    //
    logentry,"%eventname%: Turn on {substring:5:11:%eventname%} (GPIO%v{substring:10:11:%eventname%}%)."
    gpio,%v{substring:10:11:%eventname%}%,1
  elseif %eventvalue1%=0
    //
    // Value equal 0 turn off relay
    //
    logentry,"%eventname%: Turn off {substring:5:11:%eventname%} (GPIO%v{substring:10:11:%eventname%}%)."
    timerSet,{substring:10:11:%eventname%},0
    gpio,%v{substring:10:11:%eventname%}%,0
  endif
endon

on Cron#Relay4 do
  logentry,"%eventname%: Turn on Relay4."
  gpio,%v4%,1
  timerSet,4,30
endon

on Rules#Timer do
  logentry,"%eventname%: %eventvalue1% GPIO%v%eventvalue1%%"
  gpio,%v%eventvalue1%%,0
endon
What works is to send MQTT messages like this

Code: Select all

$ mosquitto_pub -h 192.168.178.63 -u espeasy -P "pass"  -t Relay4 -m "-10"
to my MQTT host (192.168.178.63) it comes in via the Home Assistant (openHAB) MQTT controller and the relay pulls for 10 seconds.
Fine.

When the cron fires on 6:42.0,10:42.0 or 15:42.0 all works fine. The relay pulls for 30 seconds (timerSet,4,30) and then releases again when the timer expires.

But on 16:42.0 the Rambo mode comes to my ESP8266 and I can see this on my loghost:

Code: Select all

Dec  6 16:42:00 ESP12F-Relay-X4 EspEasy: EVENT: Clock#Time=Tue,16:42
Dec  6 16:42:00 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  6 16:42:00 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  6 16:42:00 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  6 16:42:00 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  6 16:42:00 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  6 16:42:00 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  6 16:42:01 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  6 16:42:01 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  6 16:42:01 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  6 16:42:01 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  6 16:42:01 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  6 16:42:01 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  6 16:42:02 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  6 16:42:02 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  6 16:42:02 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  6 16:42:02 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  6 16:42:02 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  6 16:42:02 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  6 16:42:02 ESP12F-Relay-X4 EspEasy: EVENT: Env0#All=22.83,52.70,1015.53
Dec  6 16:42:03 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  6 16:42:03 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  6 16:42:03 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  6 16:42:03 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  6 16:42:03 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  6 16:42:03 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  6 16:42:04 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  6 16:42:04 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  6 16:42:04 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
... and so on...
Has anyone an idea what is happening here?
If you need further information please tell me!

I hope this is the right area for this question.
Greetings,
Lars

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

Re: Cron P081 is looping (sometimes)

#2 Post by TD-er » 07 Dec 2022, 09:56

Just looked at the source quickly and I think P081_computeNextCronTime might perhaps suffer from this bug in the cron library: https://github.com/staticlibs/ccronexpr/issues/35

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

Re: Cron P081 is looping (sometimes)

#3 Post by TD-er » 07 Dec 2022, 10:22

When this test build is ready, can you test it?
https://github.com/letscontrolit/ESPEas ... 3637516009

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#4 Post by lollypop » 07 Dec 2022, 10:28

Thanks a lot TD-er for your fast reply!

Yes! I would love to test it!

Greetings,
Lars

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

Re: Cron P081 is looping (sometimes)

#5 Post by TD-er » 07 Dec 2022, 10:38

OK, I need coffee...
Please wait for this GH Actions build: https://github.com/letscontrolit/ESPEas ... 3637757995

Edit: Did another change.. had accidentally reverted some fixes we made in the past.
So please use the (changed) link to the GH Actions build.

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#6 Post by lollypop » 07 Dec 2022, 11:34

Update Success! Rebooting...

aaand here we are:

Code: Select all

Build:⋄	20221207 - Mega
System Libraries:⋄	ESP82xx Core 2843a5ac, NONOS SDK 2.2.2-dev(38a443e), LWIP: 2.1.2 PUYA support
Git Build:⋄	HEAD_ded5122
Plugin Count:⋄	80 [Normal][Collection][Collection_A][No Debug Log]
Build Origin:	GitHub Actions
Build Time:⋄	Dec 7 2022 10:09:53
Binary Filename:⋄	ESP_Easy_mega_20221207_collection_A_ESP8266_4M1M
Build Platform:⋄	Linux-5.15.0-1023-azure-x86_64-with-glibc2.31
Git HEAD:⋄	HEAD_ded5122
Thank you a very lot so far!

I will wait for the 16:42 cron and tell you what happens.
Greetings,
Lars

User avatar
Ath
Normal user
Posts: 3415
Joined: 10 Jun 2018, 12:06
Location: NL

Re: Cron P081 is looping (sometimes)

#7 Post by Ath » 07 Dec 2022, 11:47

lollypop wrote: 07 Dec 2022, 09:13

Code: Select all

on MQTT#Relay* do
  let,1,15                               // Relay 1 is GPIO15
  let,2,14                               // Relay 2 is GPIO14
  let,3,12                               // Relay 3 is GPIO12
  let,4,13                               // Relay 4 is GPIO13
  if %eventvalue1%<0                   
    //
endon
Suggestion:
You can move these 4 assignments to "on system#boot do"event, so it isn't re-executed on every incoming MQTT#RelayN message. Of course you have to take care not to accidentally overwrite these values, but you have 'unlimited' variables at your disposal, so that shouldn't be too hard ;)
/Ton (PayPal.me)

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#8 Post by lollypop » 07 Dec 2022, 11:59

Thank you Ath,
good idea!

I'm just a noob in rules right now! I have to read more about it, but the days are just too short! Who created days that short!?!?!?

Greetings,
Lars

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

Re: Cron P081 is looping (sometimes)

#9 Post by TD-er » 07 Dec 2022, 12:24

I could add "#define SECONDS_PER_DAY 100000" in a next build. That will give you about 15% more time. Would that be enough? ;)

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#10 Post by lollypop » 07 Dec 2022, 12:41

Phew! Damn, you negotiate as hard as my boss, but 15% is a lot more than nothing! :D :D :D

User avatar
chromo23
Normal user
Posts: 821
Joined: 10 Sep 2020, 16:02
Location: germany

Re: Cron P081 is looping (sometimes)

#11 Post by chromo23 » 07 Dec 2022, 13:12

TD-er wrote: 07 Dec 2022, 12:24 I could add "#define SECONDS_PER_DAY 100000" in a next build. That will give you about 15% more time. Would that be enough?
Isn’t the maximum 4294967295 seconds?
I am no expert, but i think TD-er is holding back....
lollypop wrote: 07 Dec 2022, 12:41 but 15% is a lot more than nothing!
don't settle for that...
you have to bargain hard!

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#12 Post by lollypop » 07 Dec 2022, 15:09

Chromo23!
I love really strong coffee and stuff, but a day that lasts over 136 years is really hard. Maybe you should never overshoot the mark in negotiations.
I am not ready for a MAX_UNSIGNED_INT32!

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

Re: Cron P081 is looping (sometimes)

#13 Post by TD-er » 07 Dec 2022, 15:15

chromo23 wrote: 07 Dec 2022, 13:12
TD-er wrote: 07 Dec 2022, 12:24 I could add "#define SECONDS_PER_DAY 100000" in a next build. That will give you about 15% more time. Would that be enough?
Isn’t the maximum 4294967295 seconds?
I am no expert, but i think TD-er is holding back....
[....]
One "day" being one "Unix time" Y2K like period?
Any change here will also affect my own situation, so I have to think about the consequences for my own situation too.

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#14 Post by lollypop » 07 Dec 2022, 15:20

Maybe we should first survive Y2K38...

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

Re: Cron P081 is looping (sometimes)

#15 Post by TD-er » 07 Dec 2022, 15:46

lollypop wrote: 07 Dec 2022, 15:20 Maybe we should first survive Y2K38...
Well, that's something for tomorrow to worry about ;)

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

Re: Cron P081 is looping (sometimes)

#16 Post by TD-er » 07 Dec 2022, 17:00

OK, what was the result of your test at 16:42?

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#17 Post by lollypop » 07 Dec 2022, 19:42

Sorry, I was off for a while.

And I have to say: Nope, the fix didn't fix it.

The Cron events before worked fine like this:

Code: Select all

Dec  7 15:42:00 ESP12F-Relay-X4 EspEasy: EVENT: Clock#Time=Wed,15:42
Dec  7 15:42:00 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 15:42:00 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 15:42:00 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 15:42:00 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 15:42:00 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 15:42:00 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  7 15:42:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 15:42:00
Dec  7 15:42:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#NextExecution=2022-12-07 16:42:00
Dec  7 15:42:15 ESP12F-Relay-X4 EspEasy: WD   : Uptime 250 ConnectFailures 0 FreeMem 17048 WiFiStatus 3 ESPeasy internal wifi status: Conn. IP Init
Dec  7 15:42:22 ESP12F-Relay-X4 EspEasy: EVENT: Env0#All=23.61,66.01,1010.43
Dec  7 15:42:30 ESP12F-Relay-X4 EspEasy: EVENT: Rules#Timer=4,1
Dec  7 15:42:30 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Rules#Timer: 4 GPIO13"
Dec  7 15:42:30 ESP12F-Relay-X4 EspEasy: Rules#Timer: 4 GPIO13
Dec  7 15:42:30 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,0
Dec  7 15:42:30 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 0
But the last one looped again:

Code: Select all

Dec  7 16:42:00 ESP12F-Relay-X4 EspEasy: EVENT: Clock#Time=Wed,16:42
Dec  7 16:42:00 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 16:42:00 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 16:42:00 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 16:42:00 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 16:42:00 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 16:42:00 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  7 16:42:03 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 16:42:03 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 16:42:03 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 16:42:03 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 16:42:03 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 16:42:03 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  7 16:42:06 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 16:42:06 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 16:42:06 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 16:42:06 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 16:42:06 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 16:42:06 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 16:42:06 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 16:42:06 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 16:42:06 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 16:42:06 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 16:42:06 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  7 16:42:07 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 16:42:07 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 16:42:07 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 16:42:07 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 16:42:07 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 16:42:07 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  7 16:42:08 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 16:42:08 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 16:42:08 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 16:42:08 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 16:42:08 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 16:42:08 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  7 16:42:09 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 16:42:09 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 16:42:09 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 16:42:09 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 16:42:09 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
...
still looping
...
Dec  7 19:43:08 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 19:43:08 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 19:43:08 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 19:43:08 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 19:43:08 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 19:43:08 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
...
Do you have any further ideas? Anything I can test?

User avatar
chromo23
Normal user
Posts: 821
Joined: 10 Sep 2020, 16:02
Location: germany

Re: Cron P081 is looping (sometimes)

#18 Post by chromo23 » 07 Dec 2022, 20:34

I can confirm this. Just wanted to play around with it...

Code: Select all

0 34 6,10,15,16,20 * * *
same behavior. seems to be dependent on the last hour
Last edited by chromo23 on 07 Dec 2022, 20:43, edited 1 time in total.


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

Re: Cron P081 is looping (sometimes)

#20 Post by TD-er » 08 Dec 2022, 08:33

OK, thanks for testing, have to take a more thorough look at it.
But that won't be today.
So if anyone may find it, please let me know.

User avatar
chromo23
Normal user
Posts: 821
Joined: 10 Sep 2020, 16:02
Location: germany

Re: Cron P081 is looping (sometimes)

#21 Post by chromo23 » 08 Dec 2022, 08:54

LastExecution and NextExecution seem to be not working properly as well.
In my understanding NextExecution should be next day same time

Code: Select all

5 50 8 * * *
Bildschirmfoto 2022-12-08 um 08.50.17.png
Bildschirmfoto 2022-12-08 um 08.50.17.png (28.4 KiB) Viewed 5211 times

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#22 Post by lollypop » 08 Dec 2022, 09:09

The problem healed magically at 23:42:00 (no more Cron#Relay4 events every second):

Code: Select all

Dec  7 23:41:57 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 23:41:57 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 23:41:57 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 23:41:57 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 23:41:57 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 23:41:57 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  7 23:41:58 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 23:41:58 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 23:41:58 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 23:41:58 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 23:41:58 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 23:41:58 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  7 23:41:59 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 23:41:59 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 23:41:59 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 23:41:59 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 23:41:59 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 23:41:59 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  7 23:42:00 ESP12F-Relay-X4 EspEasy: EVENT: Clock#Time=Wed,23:42
Dec  7 23:42:00 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 23:42:00 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 23:42:00 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 23:42:00 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 23:42:00 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 23:42:00 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  7 23:42:01 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  7 23:42:01 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  7 23:42:01 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  7 23:42:01 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  7 23:42:01 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  7 23:42:01 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  7 23:42:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 06:42:00
Dec  7 23:42:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#NextExecution=2022-12-08 06:42:00
Dec  7 23:42:14 ESP12F-Relay-X4 EspEasy: EVENT: Env0#All=21.90,58.85,1007.41
Dec  7 23:42:15 ESP12F-Relay-X4 EspEasy: WD   : Uptime 730 ConnectFailures 0 FreeMem 17048 WiFiStatus 3 ESPeasy internal wifi status: Conn. IP Init
Dec  7 23:42:31 ESP12F-Relay-X4 EspEasy: EVENT: Rules#Timer=4,1
Dec  7 23:42:31 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Rules#Timer: 4 GPIO13"
Dec  7 23:42:31 ESP12F-Relay-X4 EspEasy: Rules#Timer: 4 GPIO13
Dec  7 23:42:31 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,0
Dec  7 23:42:31 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 0
Dec  7 23:42:52 ESP12F-Relay-X4 EspEasy: MQTT : Connection lost, state: Disconnected
Dec  7 23:42:52 ESP12F-Relay-X4 EspEasy: MQTT : Connected to broker with client ID: ESP12F_Relay_X4_0
Maybe there is something happening at the last time where the minutes and seconds match that day?
And obviously the LastExecution is wrong as it should be 16:42 where the drama begun:

Code: Select all

Dec  7 16:39:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 15:42:00
Dec  7 16:40:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 15:42:00
Dec  7 16:41:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 15:42:00
-----> Here should be Dec  7 16:42:04 but it isn't there and LastExecution is set to the first occurence of the day  <-----
Dec  7 16:43:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 06:42:00
Dec  7 16:44:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 06:42:00
Dec  7 16:45:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 06:42:00
Dec  7 16:46:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 06:42:00
The cron event this morning set the LastExecution time correctly (Relay4#LastExecution=2022-12-08 06:42:00):

Code: Select all

Dec  8 06:42:00 ESP12F-Relay-X4 EspEasy: EVENT: Clock#Time=Thu,6:42
Dec  8 06:42:00 ESP12F-Relay-X4 EspEasy: EVENT: Cron#Relay4
Dec  8 06:42:00 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Cron#Relay4: Turn on Relay4."
Dec  8 06:42:00 ESP12F-Relay-X4 EspEasy: Cron#Relay4: Turn on Relay4.
Dec  8 06:42:00 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,1
Dec  8 06:42:00 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 1
Dec  8 06:42:00 ESP12F-Relay-X4 EspEasy: ACT  : timerSet,4,30
Dec  8 06:42:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-08 06:42:00
Dec  8 06:42:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#NextExecution=2022-12-08 11:42:00
Dec  8 06:42:07 ESP12F-Relay-X4 EspEasy: EVENT: Env0#All=21.95,55.26,1004.04
Dec  8 06:42:15 ESP12F-Relay-X4 EspEasy: WD   : Uptime 1150 ConnectFailures 0 FreeMem 17048 WiFiStatus 3 ESPeasy internal wifi status: Conn. IP Init
Dec  8 06:42:30 ESP12F-Relay-X4 EspEasy: EVENT: Rules#Timer=4,1
Dec  8 06:42:30 ESP12F-Relay-X4 EspEasy: ACT  : logentry,"Rules#Timer: 4 GPIO13"
Dec  8 06:42:30 ESP12F-Relay-X4 EspEasy: Rules#Timer: 4 GPIO13
Dec  8 06:42:30 ESP12F-Relay-X4 EspEasy: ACT  : gpio,13,0
Dec  8 06:42:30 ESP12F-Relay-X4 EspEasy: GPIO : port#13: set to 0
Just some points I saw in the logs.
Greetings,
Lars
Last edited by lollypop on 08 Dec 2022, 09:20, edited 1 time in total.

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

Re: Cron P081 is looping (sometimes)

#23 Post by TD-er » 08 Dec 2022, 09:19

Having last and next being the same, is for sure a good explanation why it triggers so many events.

But I find it very strange to see that it sometimes seems to work and sometimes it doesn't.
One thing that keeps bugging me is that these timestamps are being stored in the UserVar array, which is a float.
It is being stored and retrieved using a special function which does try to store it as an int, thus we store it as a byte array.
But what if -for some reason- this is not done correct?
Then we would miss out on some resolution.

Symptoms would be like serious rounding errors. (upto minutes)

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#24 Post by lollypop » 08 Dec 2022, 09:22

Careful!
It is not the same, day is different:
Dec 7 23:42:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 06:42:00
Dec 7 23:42:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#NextExecution=2022-12-08 06:42:00

NextExecution was correct, but LastExecution was not.

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

Re: Cron P081 is looping (sometimes)

#25 Post by TD-er » 08 Dec 2022, 09:36

And this is when running the test build including the intended fix for the cron library?

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#26 Post by lollypop » 08 Dec 2022, 10:46

Right, this is your build from yesterday.

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#27 Post by lollypop » 09 Dec 2022, 19:38

lollypop wrote: 08 Dec 2022, 09:22 Careful!
It is not the same, day is different:
Dec 7 23:42:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 06:42:00
Dec 7 23:42:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#NextExecution=2022-12-08 06:42:00

NextExecution was correct, but LastExecution was not.
Sorry, you are definetly right!
Dec 7 16:41:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 15:42:00
Dec 7 16:41:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#NextExecution=2022-12-07 16:42:00
Dec 7 16:43:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 06:42:00
Dec 7 16:43:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#NextExecution=2022-12-07 06:42:00
Dec 7 16:44:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-07 06:42:00
Dec 7 16:44:04 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#NextExecution=2022-12-07 06:42:00
...
Dec 9 16:41:05 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-09 15:42:00
Dec 9 16:41:05 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#NextExecution=2022-12-09 16:42:00
Dec 9 16:42:05 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-09 06:42:00
Dec 9 16:42:05 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#NextExecution=2022-12-09 06:42:00
Dec 9 16:43:05 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#LastExecution=2022-12-09 06:42:00
Dec 9 16:43:05 ESP12F-Relay-X4 EspEasy: EVENT: Relay4#NextExecution=2022-12-09 06:42:00

The lines of my message were after self healing.
Greetings,
Lars

User avatar
chromo23
Normal user
Posts: 821
Joined: 10 Sep 2020, 16:02
Location: germany

Re: Cron P081 is looping (sometimes)

#28 Post by chromo23 » 09 Dec 2022, 20:56

NextExecution is not able to see into future (next day) and that`s why cron fails i guess.

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#29 Post by lollypop » 20 Dec 2022, 10:14

Small update with an workaround.

As it is always just the last entry that runs in this bug I just added a dummy entry at the end (18:42):

0 42 6,11,15,16,18 * * *

and then just ignored events after 18:00:

Code: Select all

on Cron#Relay4 do
  if %syshour% >= 18
    logentry,"%eventname%: Not turning on Relay4 after 18:00." 
  else
    logentry,"%eventname%: Turn on Relay4." 
    gpio,%v4%,1
    timerSet,4,30
  endif
endon
Stupid way, but it works.
Looking forward for a fix next year maybe :-)?.

So have a relaxed christmas time and a good jump into 2023!
Lars

SirWant
Normal user
Posts: 12
Joined: 04 Feb 2023, 16:38

Re: Cron P081 is looping (sometimes)

#30 Post by SirWant » 17 Apr 2023, 10:35

Yes, cron doesn't work. Works only as a looptimer - "*/x".
For example:
Сurrent Time = 10:30, Cron = 0 0 10 * * * - Loop immediately. Cron = 0 40 10 * * * - Loop after 10:40.

User avatar
chromo23
Normal user
Posts: 821
Joined: 10 Sep 2020, 16:02
Location: germany

Re: Cron P081 is looping (sometimes)

#31 Post by chromo23 » 04 Dec 2023, 10:41

SirWant wrote: 17 Apr 2023, 10:35 Yes, cron doesn't work.
lollypop wrote: 20 Dec 2022, 10:14 Small update with an workaround.
FYI: TD-er just updated the library of the cron plugin, which seems to solve all the issues. :)
You can test it here: https://github.com/letscontrolit/ESPEas ... 7084301371

Edit: for now, allowed options can be found here: https://github.com/letscontrolit/ESPEas ... 1838149989

lollypop
Normal user
Posts: 14
Joined: 06 Dec 2022, 20:41
Location: Hamburg, EU

Re: Cron P081 is looping (sometimes)

#32 Post by lollypop » 05 Dec 2023, 11:39

Thank you very lot for notifying me!

As far as I can tell the new version works fine. Installed it yesterday and it does not loop after the last time that day.
Great <3!
We can close this now.

Greetings from afar

Lars

Post Reply

Who is online

Users browsing this forum: Ahrefs [Bot] and 26 guests