Time zone issues?

[rsarwar87]

Hi i noticed that something odd on the log: @ TS 00:15:52. it said now 09-19 23:14:00. Tim zone is Europe/London both on appdaemon.yml and apps.yaml. My first charge slot was at 23:30-00:00. tht was triggered correctly, but at 23:45, th aemon changed the start tim to 22:30-2300.

2023-09-20 00:15:52.565870 INFO pred_bat: Charge window will be: 2023-09-21 05:00:00+01:00 - 2023-09-21 05:30:00+01:00 - current soc 78.target 100
2023-09-20 00:15:52.567479 INFO pred_bat: Configuring charge window now (now 09-19 23:14:00 target set_window_minutes 30 charge start time 09-20 05:00:00
2023-09-20 00:15:52.569196 INFO pred_bat: Inverter 0 charge window is 05:00:00 - 05:30:00, being changed to 05:00:00 - 05:30:00
**2023-09-20 00:15:52.570634 INFO pred_bat: Not setting charging SOC as we are not within the window (now 09-19 23:14:00 target set_soc_minutes 30 charge start time 09-20 05:00:00)**
2023-09-20 00:15:52.572087 INFO pred_bat: Adjust reserve to default (as set_reserve_enable is true)
2023-09-20 00:15:52.573503 INFO pred_bat: Inverter 0 Current reserve is 4.0 already at target
2023-09-20 00:15:52.574932 INFO pred_bat: Completed run status Idle
2023-09-20 00:15:52.586617 INFO AppDaemon: Previous message repeated 1 times
2023-09-20 00:15:52.587008 WARNING AppDaemon: Excessive time spent in callback 'update_time_loop() in pred_bat', Thread 'thread.thread-1' - now complete after 82.585794 seconds (limit=60.0)

also plots have gone weird after midnight.

edit:plots came back okay at 0100 and this was in the log:

2023-09-20 01:04:55.021018 INFO pred_bat: Inverter 0 Updated start and end charge window to 00:30:00 - 01:00:00 (old 00:46:00 - 01:00:00)

[rsarwar87]

also sometimes i notice that the inverter oes not stop charging at the end of a slot, most likely if the soc target has not been met. would it be worth issuing a enableChargeTarget(false) at the end of the window just to be sure?

[springfall2008]

Does the time in the left hand side of the log match the correct time, and is the inverter time aligned correctly to this too?

[springfall2008]

Charts going wrong at midnight I've seen before, I must get around to debugging this but I'm always in bed!

[rsarwar87]

2023-09-20 09:53:11.138063 INFO pred_bat: Invertor time 2023-09-20 09:52:54+01:00 AppDeamon time 2023-09-20 09:53:08.003787+01:00 difference -0.25 minutes
2023-09-20 09:53:30.200572 INFO pred_bat: Configuring charge window now (now 09-20 08:53:00 target set_window_minutes 30 charge start time 09-21 05:00:00

inverter times looks okay. target seems off. I can have a look in the code when i get off work - but you may be able to track it down more quickly.

It seems my 0500 charge slot was triggered correctly and did change mid process. so clearly seems very intermittent. ill have a look at the complete log. it might be connected to the this midnight/UTC thing.

PS: Do you happen to have any documentation on the rest.py wrapper on giv_tcp? Trying to work out how to shift house load from the battery to the grid when import rates are below a fixed threshold.

[rsarwar87]

charge time set correctly at 2246 of 2330, then goes into a state if "not setting charge time" (still 2330) and then finally decides to set it to 2230 @ 2350

again at 0258, setting at 0130

and 0333, setting at 0230

this is what the battery actually ended up doing.

and the log from givTCP

2023-09-19 22:46:19,237 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 23:30 - 00:00
2023-09-19 22:46:22,741 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-19 22:46:46,378 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-19 23:51:18,401 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 22:30 - 23:00
2023-09-19 23:51:25,810 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-19 23:51:40,928 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-19 23:51:51,464 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 92
2023-09-19 23:51:57,678 - Inv1 - write       -  [INFO    ] - Setting Charge Target 92 was a success
2023-09-19 23:52:09,212 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 92
2023-09-19 23:52:13,689 - Inv1 - write       -  [INFO    ] - Setting Charge Target 92 was a success
2023-09-19 23:56:03,377 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 88
2023-09-19 23:56:06,933 - Inv1 - write       -  [INFO    ] - Setting Charge Target 88 was a success
2023-09-19 23:56:19,984 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 88
2023-09-19 23:56:26,186 - Inv1 - write       -  [INFO    ] - Setting Charge Target 88 was a success
2023-09-20 00:01:14,902 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 05:00 - 05:30
2023-09-20 00:01:24,002 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 00:01:39,318 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 00:01:57,049 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 00:44:55,773 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 05:00 - 05:30
2023-09-20 00:44:59,265 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 00:45:15,810 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 01:04:38,157 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 00:30 - 01:00
2023-09-20 01:04:43,416 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 01:04:57,129 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 02:03:49,188 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 05:00 - 05:30
2023-09-20 02:03:52,442 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 02:04:08,812 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 02:58:51,487 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 01:30 - 02:00
2023-09-20 02:58:59,230 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 02:59:14,026 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 02:59:24,427 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 96
2023-09-20 02:59:33,907 - Inv1 - write       -  [INFO    ] - Setting Charge Target 96 was a success
2023-09-20 03:03:48,100 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 05:00 - 05:30
2023-09-20 03:03:51,356 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 03:04:06,685 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 03:33:47,377 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 02:30 - 03:00
2023-09-20 03:33:50,848 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 03:34:05,985 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 03:34:20,362 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 94
2023-09-20 03:34:22,615 - Inv1 - write       -  [INFO    ] - Setting Charge Target 94 was a success
2023-09-20 03:43:30,385 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 100
2023-09-20 03:43:32,693 - Inv1 - write       -  [INFO    ] - Setting Charge Target 100 was a success
2023-09-20 03:58:30,680 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 99
2023-09-20 03:58:32,917 - Inv1 - write       -  [INFO    ] - Setting Charge Target 99 was a success
2023-09-20 04:03:47,934 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 05:00 - 05:30
2023-09-20 04:03:48,824 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 failed: (<class 'AssertionError'>, AssertionError('Unexpected response from remote end: <givenergy_modbus.pdu.ErrorResponse object at 0x7fabc1dde0>'), <traceback object at 0x7fabc38900>)
2023-09-20 04:04:05,086 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 05:00 - 05:30
2023-09-20 04:04:09,778 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 04:04:24,292 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 04:33:47,388 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 03:30 - 04:00
2023-09-20 04:33:50,839 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 04:34:04,926 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 04:34:19,346 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 100
2023-09-20 04:34:21,399 - Inv1 - write       -  [INFO    ] - Setting Charge Target 100 was a success
2023-09-20 04:59:27,526 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 95
2023-09-20 04:59:36,224 - Inv1 - write       -  [INFO    ] - Setting Charge Target 95 failed: (<class 'AssertionError'>, AssertionError('Unexpected response from remote end: Modbus Error: [Input/Output] No Response received from the remote unit/Unable to decode response'), <traceback object at 0x7fabc3c300>)
2023-09-20 04:59:45,087 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 95
2023-09-20 04:59:51,021 - Inv1 - write       -  [INFO    ] - Setting Charge Target 95 was a success
2023-09-20 05:03:50,604 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 05:00 - 05:30
2023-09-20 05:03:54,071 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 05:04:11,414 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 05:08:47,435 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 04:00 - 04:30
2023-09-20 05:08:54,819 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 05:09:09,799 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 05:09:20,068 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 94
2023-09-20 05:09:26,432 - Inv1 - write       -  [INFO    ] - Setting Charge Target 94 was a success
2023-09-20 05:18:30,192 - Inv1 - write       -  [INFO    ] - Setting Charge Target to: 100
2023-09-20 05:18:32,426 - Inv1 - write       -  [INFO    ] - Setting Charge Target 100 was a success
2023-09-20 05:33:52,263 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 04:00 - 05:00
2023-09-20 05:33:55,731 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 05:34:12,207 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 05:38:46,712 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 04:00 - 05:30
2023-09-20 05:38:55,063 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 05:39:09,963 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 06:33:48,671 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 00:30 - 01:00
2023-09-20 06:33:52,084 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 06:34:07,140 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 06:53:48,698 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 00:30 - 06:00
2023-09-20 06:53:54,019 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 06:54:10,164 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 07:03:51,430 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 00:30 - 01:00
2023-09-20 07:03:54,879 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 07:04:09,955 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success
2023-09-20 09:03:46,781 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 05:00 - 05:30
2023-09-20 09:03:50,233 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2023-09-20 09:04:05,780 - Inv1 - write       -  [INFO    ] - Setting Charge Enable was a success

[rsarwar87]

I don't see anything wrong as such, other than it can't make it mind up. Was the end result okay?

both times the charging halted when it decided to move things by 1 hour. i had to pause the appdaemon container manually set the window

Based on the prediction plot, the charging window did not move, its just that the python code could not convert that time from UTC?

[springfall2008]

Sorry posted on the wrong account. "both times the charging halted when it decided to move things by 1 hour."

Why is this a problem as such?

[rsarwar87]

Aaa, I am on agile.

Same on flux flux to an extent, I would not want it to start an hour earlier accidentally.

[springfall2008]

I'm still really struggling to understand exactly the issue, are you saying the Predbat chart shows it should charge at say 2am but it's actually charging at 3am?

Or are you saying Predbat just changed its mind and decided to charge later?

[springfall2008]

Can you snapshot the history of predbat.status?

[rsarwar87]

the problem was on AppDaemon,when run as docker, despite setting tz on appdaemon.yaml, it it does not seem to want to work all the time, either because of the way the times are retrieved in the code, or app daemon/python issue.

Sorted by passing /etc/localtime from the rpi4