Schedule event actions have timezone conversion bug(s)

[fhteagle]

Using nightly build from 03 March. If OpenEVSE has no manual override or active claims, adding a "disable" schedule entry does not activate on save.

Steps to reproduce:

1. Start from no schedule set, no override set, no claims set
2. Add an active timer entry later than the current time of day
3. Add a disable timer entry that is later than today, but should would have fired yesterday instead if it had been set at that time.
4. Note that the resulting OpenEVSE mode is "active", during the period of the day defined by the new schedule as "should be disabled"

IIRC, in a previous revision of the GUI v2 this was working as expected.

[fhteagle]

Also, just tried this again on my older unit, and got different results. Bug report above has main OpenEVSE firmware 8.2.2. Older unit is on 7.1.3. Older unit works as expect with respect to newly established schedule, new unit consistently displays the bug as given above. I wonder if there is a logic issue between GUIv2 and 8.2.2 ?

[fhteagle]

New data point: old unit with 7.1.3 is now acting as if schedule logic is reversed also. As in, "activated at" schedule time actually disabled the unit...

[KipK]

That's odd . Can you post your /schedule endpoint?

[KipK]

I think it comes from this commit https://github.com/OpenEVSE/ESP32_WiFi_V4.x/commit/169c7893324c9c52b495dc89491d3f2ec487bae6

Bug in esp fw

[fhteagle]

Older unit with 7.1.3:

 [{"id":1,"state":"active","time":"10:30:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":2,"state":"disabled","time":"15:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]}] 

Newer unit with 8.2.2:

[{"id":1,"state":"active","time":"10:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":2,"state":"disabled","time":"16:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]}]

If I swap the "disabled" and "active" entries, I get the behavior I expect. So yeah sounds like there is a logic flaw in determining what was the most recent past schedule event.........

[fhteagle]

Do we need to move this issue into https://github.com/OpenEVSE/ESP32_WiFi_V4.x/issues ?

I do not think it is a GUI v2 issue after all.

[KipK]

I think Ive fixed it, can you try this fw ? https://drive.google.com/file/d/1FHz4VDTBBQMi9Lvw2HEtp4XSeoSVeEze/view?usp=sharing

This also has new EnergyMeter and new Wifi manager

[KipK]

Seems to work here, can't reproduce the bug with the fix.

[KipK]

@fhteagle , you're still there ? Can you test the link above ?

[fhteagle]

Just tried it, still seeing incorrect schedule results:

I think I have drilled down to a more accurate causal pattern though. Its reading the first schedule line only, and ignoring the rest of the defined schedule lines.

[fhteagle]

I also found a secondary bug in the firmware from your Google drive link. Pressing "Close" on schedule edit popup changes that line in the UI, but not in the /schedule endpoint or status block:

[{"id":4,"state":"disabled","time":"10:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":3,"state":"active","time":"08:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]}]

[fhteagle]

Third schedule input bug: I just used "new timer" button, picked a random time, and hit "save", but it edited the highest id schedule item instead. Did it again to confirm.

[fhteagle]

[{"id":11,"state":"disabled","time":"11:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":2,"state":"disabled","time":"02:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":3,"state":"active","time":"03:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":4,"state":"disabled","time":"04:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":5,"state":"active","time":"05:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":6,"state":"disabled","time":"07:20:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":7,"state":"active","time":"07:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":8,"state":"active","time":"08:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":9,"state":"disabled"}]

Should this id 9 line be possible?

[KipK]

Here is the fw with new EnergyMeter without the previous fix then, it perhaps introduced other bugs.

https://drive.google.com/file/d/1FN0yoHfwGPPeE2eWDeX5uFcPom5iKT-h/view?usp=sharing

I still can't reproduce it also, so I have no clue yet:

[KipK]

I also found a secondary bug in the firmware from your Google drive link. Pressing "Close" on schedule edit popup changes that line in the UI, but not in the /schedule endpoint or status block:

[{"id":4,"state":"disabled","time":"10:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},
{"id":3,"state":"active","time":"08:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]}]

this is the only one I can reproduce :) Will fix that

[fhteagle]

Should "Close" button on the schedule edit popup be changed to "Cancel"? As in cancel the changes you are making....

[fhteagle]

@KipK I just tried the second firmware that you linked. I could not induce the schedule problem with only two schedule items defined, but I could consistently create a not-followed schedule with 3 or more schedule items defined.

[KipK]

create a not-followed schedule with 3 or more schedule items defined.

still the same can't reproduce :

Can you empty the scheduler and check after the /schedule endpoint if it's really empty ?

edit: thinking about something, can you check also the timers time are correct in the endpoint ? As you have 12h format, perhaps time recorded is incorrect and I should fix that

[KipK]

{"id":9,"state":"disabled"}]

clearly this is wrong

[fhteagle]

The {"id":9,"state":"disabled"}] /schedule endpoint line item did fully display after I had deleted some other schedule items. It looks like the /schedule endpoint cannot display more than a certain number of items. Not sure its a real problem, as I doubt anyone would ever define more than 6 schedule items in a day in reality. I did wonder if the scheduling logic was seeing/using a truncated schedule item elsewhere by accident, though...

I think the max is 50 events according to the code, I've locked to this in the nxt versions. But I'm not sure the WiFi module has enough allocated memory for such a big json output. We will have to verify that

[fhteagle]

With nightly build from this morning:

When you say you cannot replicate 3 schedule items misbehavior, are you always testing schedule items in the pattern of ADA, or DAD ? in this case, if the logic was incorrectly applying first A or D in the pattern, it will make it look like last A or D has been correctly considered.

[KipK]

yep, none of this here, works perfectly:

forget the nightly build if you test energymeter for now as it will cause confusions. and the wifi fw branch for uiv2 & master is far behind this build. Anyway there's no change on scheduler.

This one bug will be hard to find 🤔

Edit: ho I have not seen the disable at doesn't appear in my case ( Those are coming from the /schedule/plan endpoint )

@fhteagle , can you output booth /schedules and /schedules/plan with your non working case?

[KipK]

@jeremypoulter , I tag you here to follow this

[fhteagle]

Okay, step by step adding schedule items, using EnergyMeter but no schedule fix from Google Drive above:

Single 10 AM active item, works as expected: https://pastebin.com/WnNgy4cv

Two items, works as expected: https://pastebin.com/Vm3TdyKn

Three items, third should have the unit activated at 9:13AM local, but does not: https://pastebin.com/f7ZNqLD3

Three items, correctly disabled, but no next active line in status block: https://pastebin.com/f5pDNu0g

Three items, incorrectly activated: https://pastebin.com/DDBNJXJH

Hope my descriptions are clear enough. Let me know what other test cases you want.

[KipK]

Ok thanks. so /schedule/plan endpoint is wrong with multiple timers in some case. This feature has not been deeply tested when implemented as the old UI was still using only 2 timers ( 1 activated and one disabled ) There's probably a long term bug laying around the scheduler here. Luckily, we have a clue of what's happening now :)

[jeremypoulter]

@KipK I wonder if the Scheduler UI should be rethought. Although the backend allows for odd number of enteries in the schedule, I don't think there is any practical reason why you would need to do that so maybe only ever alow the schedule to beset in pairs of active/disabled?

[KipK]

If you rewrite the scheduler API to use pairs natively ,( one entry has an active and disable ) with actual structure, it's a pain to match a pair if they are not in correct sequence.

Btw I was using the scheduler with only one entry to set dynamically low cost / high cost time when I receive a signal from the main counter. ( when receiving low cost signal it creates a new schedule with an enable , then delete it and create a disable when receiving the high cost signal. )

But I can live without as I plan to extend the Ohm Connect feature to make it more universal.

[fhteagle]

Testing energymeter-0.2 version from KipK GoogleDrive, got a failure of the schedule with just two schedule items set:

/schedule:

[{"id":1,"state":"active","time":"09:31:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},{"id":2,"state":"disabled","time":"15:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]}]

/schedule/plan:

{"current_day":"wednesday","current_offset":59834,"next_event_delay":61323,"current_event":{"id":2,"state":"disabled","time":"15:00:00","day":"wednesday","offset":54000,"start_offset":54000,"diff":0,"duration":67157},"next_event":{"id":1,"state":"active","time":"09:31:00","day":"thursday","offset":34260,"start_offset":34757,"diff":497,"duration":19243},"sunday":[{"id":1,"state":"active","time":"09:31:00","day":"sunday","offset":34260,"start_offset":33256,"diff":-1004,"duration":20744},{"id":2,"state":"disabled","time":"15:00:00","day":"sunday","offset":54000,"start_offset":54000,"diff":0,"duration":67677}],"monday":[{"id":1,"state":"active","time":"09:31:00","day":"monday","offset":34260,"start_offset":35277,"diff":1017,"duration":18723},{"id":2,"state":"disabled","time":"15:00:00","day":"monday","offset":54000,"start_offset":54000,"diff":0,"duration":67480}],"tuesday":[{"id":1,"state":"active","time":"09:31:00","day":"tuesday","offset":34260,"start_offset":35080,"diff":820,"duration":18920},{"id":2,"state":"disabled","time":"15:00:00","day":"tuesday","offset":54000,"start_offset":54000,"diff":0,"duration":67741}],"wednesday":[{"id":1,"state":"active","time":"09:31:00","day":"wednesday","offset":34260,"start_offset":35341,"diff":1081,"duration":18659},{"id":2,"state":"disabled","time":"15:00:00","day":"wednesday","offset":54000,"start_offset":54000,"diff":0,"duration":67157}],"thursday":[{"id":1,"state":"active","time":"09:31:00","day":"thursday","offset":34260,"start_offset":34757,"diff":497,"duration":19243},{"id":2,"state":"disabled","time":"15:00:00","day":"thursday","offset":54000,"start_offset":54000,"diff":0,"duration":67396}],"friday":[{"id":1,"state":"active","time":"09:31:00","day":"friday","offset":34260,"start_offset":34996,"diff":736,"duration":19004},{"id":2,"state":"disabled","time":"15:00:00","day":"friday","offset":54000,"start_offset":54000,"diff":0,"duration":65733}],"saturday":[{"id":1,"state":"active","time":"09:31:00","day":"saturday","offset":34260,"start_offset":33333,"diff":-927,"duration":20667},{"id":2,"state":"disabled","time":"15:00:00","day":"saturday","offset":54000,"start_offset":54000,"diff":0,"duration":65656}]}

I also set start random time to just 1 second to make sure that was not the issue, edited the activate start time to be way earlier, etc, but still seeing the failure.

[KipK]

Looking at the /schedule/plan

{"current_day":"wednesday","current_offset":59834,"next_event_delay":61323,"current_event":{"id":2,"state":"disabled","time":"15:00:00","day":"wednesday","offset":54000,"start_offset":54000,"diff":0,"duration":67157},"next_event": ...

@jeremypoulter , you can see It set what should be the next event as the current_event.

@fhteagle Is it the same if you put the disabled timer first and then the enabled ?

[fhteagle]

Still seeing incorrect disabled by schedule state after defining disable time first:

/schedule:

[{"id":1,"state":"disabled","time":"15:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]},{"id":2,"state":"active","time":"09:00:00","days":["sunday","monday","tuesday","wednesday","thursday","friday","saturday"]}]

/schedule/plan:

{"current_day":"wednesday","current_offset":61673,"next_event_delay":57127,"current_event":{"id":1,"state":"disabled","time":"15:00:00","day":"wednesday","offset":54000,"start_offset":54000,"diff":0,"duration":64800},"next_event":{"id":2,"state":"active","time":"09:00:00","day":"thursday","offset":32400,"start_offset":32400,"diff":0,"duration":21600},"sunday":[{"id":2,"state":"active","time":"09:00:00","day":"sunday","offset":32400,"start_offset":32400,"diff":0,"duration":21600},{"id":1,"state":"disabled","time":"15:00:00","day":"sunday","offset":54000,"start_offset":54000,"diff":0,"duration":64800}],"monday":[{"id":2,"state":"active","time":"09:00:00","day":"monday","offset":32400,"start_offset":32400,"diff":0,"duration":21600},{"id":1,"state":"disabled","time":"15:00:00","day":"monday","offset":54000,"start_offset":54000,"diff":0,"duration":64800}],"tuesday":[{"id":2,"state":"active","time":"09:00:00","day":"tuesday","offset":32400,"start_offset":32400,"diff":0,"duration":21600},{"id":1,"state":"disabled","time":"15:00:00","day":"tuesday","offset":54000,"start_offset":54000,"diff":0,"duration":64799}],"wednesday":[{"id":2,"state":"active","time":"09:00:00","day":"wednesday","offset":32400,"start_offset":32399,"diff":-1,"duration":21601},{"id":1,"state":"disabled","time":"15:00:00","day":"wednesday","offset":54000,"start_offset":54000,"diff":0,"duration":64800}],"thursday":[{"id":2,"state":"active","time":"09:00:00","day":"thursday","offset":32400,"start_offset":32400,"diff":0,"duration":21600},{"id":1,"state":"disabled","time":"15:00:00","day":"thursday","offset":54000,"start_offset":54000,"diff":0,"duration":64800}],"friday":[{"id":2,"state":"active","time":"09:00:00","day":"friday","offset":32400,"start_offset":32400,"diff":0,"duration":21600},{"id":1,"state":"disabled","time":"15:00:00","day":"friday","offset":54000,"start_offset":54000,"diff":0,"duration":64800}],"saturday":[{"id":2,"state":"active","time":"09:00:00","day":"saturday","offset":32400,"start_offset":32400,"diff":0,"duration":21600},{"id":1,"state":"disabled","time":"15:00:00","day":"saturday","offset":54000,"start_offset":54000,"diff":0,"duration":64800}]}

[KipK]

so this should happends too with stable fw and old UI with the same use case. I see no change on this part.

[fhteagle]

@KipK .... is there a particular version you want me to roll back to and test to try to bisect for a behavior change? I have kept copies of the nightly builds going back almost a month or so.

[KipK]

whatever, should be the same for all, good news I could reproduce it too with the same use case :)

[KipK]

ok interesting thing, it only happends when the failing timer is just from the same hour as current time. If you put it one hour sooner it then works ok.

[fhteagle]

Copying traffic from https://github.com/OpenEVSE/ESP32_WiFi_V4.x/issues/560 : Appears to be incorrect timezone application as root cause.

[KipK]

everything seems to be ok now with latest PR https://github.com/OpenEVSE/ESP32_WiFi_V4.x/pull/569. tz branch here is ready for merge.