springfall2008 / batpred

Home battery prediction and charging automation for Home Assistant, supporting many inverter types
https://springfall2008.github.io/batpred/
129 stars 44 forks source link

Predbat Planning broken apparently due to inverter/Appdaemon clocks discrepancy #1292

Open jrwm47 opened 4 months ago

jrwm47 commented 4 months ago

Predbat planning and control appears to have halted due to a huge and increasing reported discrepancy between inverter and AppDaemon times. Appdaemon time is correct. Inverter time is way out. Do I have a hardware RTC problem?

After several weeks of very careful setting up in Monitor mode, a week ago I finally gave Predbat control of my GE AIO. Initially it appeared to be working extremely well. But today it has started showing an SOC (59%) [see screenshot below] in the plan which is completely different from that reported by GivEnergy and WonderWatt (control switched off), both reporting (95%).

The log file [below] reports a 1563.5 minute inverter/Appdaemon time discrepancy and says:

2024-07-07 16:46:54.345839: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 16:46:54.389117: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode.

Predbat version 1.1.7. I have deliberately not upgraded to 1.1.8.

Environment details GivEnergy 13.5kWh All-In-One without Gateway; CTs hardwired to inverter by installer HAOS on RasPi 4 on very reliable LAN 3.6kW PV with Solis inverter eddi and harvi Octopus Agile

1) Ever since my AIO was installed, GE platform and app have reported completely crazy Energy numbers - *,000s of kWh per day! Power numbers however look ok. I have reported the problem, with screenshots, numerous times to GE support but they have gone silent on me.

2) I struggled for days to get the GivTCP/Predbat pipeline to work. Only when I switched to the GivTCP_Beta Add-on did GivTCP/predbat start reading the inverter serial number and predbat planning started.

3) I used your most recent integrated Add-on installation sequence, without an explicit Appdaemon installation. But Appdaemon clock appears to be running and checked by predbat.

4) I only enabled iBoost for our eddi yesterday and I suspect that was when the predbat planning problem started. Could this be relevant?

YAML

------------------------------------------------------------------

JM v1.0 1/7/24

------------------------------------------------------------------


pred_bat: module: predbat class: PredBat

Sets the prefix for all created entities in HA - only change if you want to run more than once instance

prefix: predbat

Timezone to work in

timezone: Europe/London

Currency, symbol for main currency second symbol for 1/100s e.g. $ c or £ p or e c

currency_symbols:

Screenshots image

Log file 2024-07-07 16:45:04.730723: Warn: Historical day 3 has 220 minutes of gap in the data, filled from 15.01 kWh to make new average 17.71 kWh (percent 85%) 2024-07-07 16:45:07.135699: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 16:45:07.135508+01:00 this is -1563.5 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 16:45:07.195143: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 16:45:07.135508+01:00 this is -1563.5 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 16:45:07.195936: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 16:45:07.196145: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 16:45:22.262355: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 16:45:22.304334: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 16:46:43.526800: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 16:46:43.525904+01:00 this is -1565.1 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 16:46:43.589826: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 16:46:43.525904+01:00 this is -1565.1 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 16:46:43.590255: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 16:46:43.590406: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 16:46:54.345839: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 16:46:54.389117: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 16:50:04.257538: Warn: Historical day 2 has 300 minutes of gap in the data, filled from 24.45 kWh to make new average 30.89 kWh (percent 79%) 2024-07-07 16:50:04.271476: Warn: Historical day 3 has 220 minutes of gap in the data, filled from 15.03 kWh to make new average 17.74 kWh (percent 85%) 2024-07-07 16:50:06.669983: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 16:50:06.669535+01:00 this is -1568.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 16:50:06.726236: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 16:50:06.669535+01:00 this is -1568.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 16:50:06.726467: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 16:50:06.726815: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 16:50:21.809157: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 16:50:21.847880: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 16:55:04.809417: Warn: Historical day 2 has 305 minutes of gap in the data, filled from 24.43 kWh to make new average 30.99 kWh (percent 79%) 2024-07-07 16:55:04.823307: Warn: Historical day 3 has 220 minutes of gap in the data, filled from 14.96 kWh to make new average 17.65 kWh (percent 85%) 2024-07-07 16:55:06.405542: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 16:55:06.405220+01:00 this is -1573.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 16:55:06.461021: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 16:55:06.405220+01:00 this is -1573.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 16:55:06.461284: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 16:55:06.461417: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 16:55:22.604409: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 16:55:22.644932: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 16:56:43.287343: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 16:56:43.287052+01:00 this is -1575.1 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 16:56:43.347646: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 16:56:43.287052+01:00 this is -1575.1 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 16:56:43.348871: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 16:56:43.349327: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 16:56:54.086338: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 16:56:54.129923: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 17:00:05.575202: Warn: Historical day 2 has 310 minutes of gap in the data, filled from 24.42 kWh to make new average 31.12 kWh (percent 78%) 2024-07-07 17:00:05.588706: Warn: Historical day 3 has 220 minutes of gap in the data, filled from 14.87 kWh to make new average 17.55 kWh (percent 85%) 2024-07-07 17:00:07.977930: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:00:07.977415+01:00 this is -1578.5 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:00:08.030736: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:00:07.977415+01:00 this is -1578.5 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:00:08.030950: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 17:00:08.031044: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 17:00:35.748934: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 17:00:35.791028: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 17:05:05.013631: Warn: Historical day 2 has 315 minutes of gap in the data, filled from 24.42 kWh to make new average 31.26 kWh (percent 78%) 2024-07-07 17:05:05.027369: Warn: Historical day 3 has 220 minutes of gap in the data, filled from 14.87 kWh to make new average 17.55 kWh (percent 85%) 2024-07-07 17:05:07.424188: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:05:07.423937+01:00 this is -1583.5 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:05:07.479758: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:05:07.423937+01:00 this is -1583.5 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:05:07.480008: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 17:05:07.480302: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 17:05:22.759563: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 17:05:22.802803: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 17:06:44.210321: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:06:44.209840+01:00 this is -1585.12 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:06:44.268241: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:06:44.209840+01:00 this is -1585.12 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:06:44.268594: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 17:06:44.268830: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 17:06:55.022924: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 17:06:55.067824: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 17:10:05.180930: Warn: Historical day 2 has 320 minutes of gap in the data, filled from 24.39 kWh to make new average 31.36 kWh (percent 78%) 2024-07-07 17:10:05.194397: Warn: Historical day 3 has 220 minutes of gap in the data, filled from 14.89 kWh to make new average 17.58 kWh (percent 85%) 2024-07-07 17:10:06.794276: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:10:06.793791+01:00 this is -1588.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:10:06.853688: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:10:06.793791+01:00 this is -1588.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:10:06.853860: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 17:10:06.853932: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 17:10:21.975541: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 17:10:22.023041: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 17:15:04.262073: Warn: Historical day 2 has 325 minutes of gap in the data, filled from 24.36 kWh to make new average 31.46 kWh (percent 77%) 2024-07-07 17:15:04.275478: Warn: Historical day 3 has 220 minutes of gap in the data, filled from 14.93 kWh to make new average 17.62 kWh (percent 85%) 2024-07-07 17:15:06.668234: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:15:06.667964+01:00 this is -1593.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:15:06.723231: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:15:06.667964+01:00 this is -1593.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:15:06.723437: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 17:15:06.723542: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 17:15:25.335618: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 17:15:25.381008: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 17:16:46.697474: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:16:46.697172+01:00 this is -1595.15 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:16:46.758265: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:16:46.697172+01:00 this is -1595.15 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:16:46.758651: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 17:16:46.758748: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 17:16:57.893760: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 17:16:57.938488: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 17:20:05.156174: Warn: Historical day 2 has 330 minutes of gap in the data, filled from 24.33 kWh to make new average 31.56 kWh (percent 77%) 2024-07-07 17:20:05.172692: Warn: Historical day 3 has 220 minutes of gap in the data, filled from 14.86 kWh to make new average 17.54 kWh (percent 85%) 2024-07-07 17:20:06.582473: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:20:06.582219+01:00 this is -1598.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:20:06.636865: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:20:06.582219+01:00 this is -1598.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:20:06.637055: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 17:20:06.637142: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 17:20:23.519813: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 17:20:23.560145: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 17:25:04.750198: Warn: Historical day 2 has 335 minutes of gap in the data, filled from 24.28 kWh to make new average 31.64 kWh (percent 77%) 2024-07-07 17:25:04.764735: Warn: Historical day 3 has 220 minutes of gap in the data, filled from 14.91 kWh to make new average 17.6 kWh (percent 85%) 2024-07-07 17:25:06.413383: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:25:06.413126+01:00 this is -1603.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:25:06.467376: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:25:06.413126+01:00 this is -1603.48 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:25:06.467606: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 17:25:06.467725: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 17:25:22.745612: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 17:25:22.791716: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode 2024-07-07 17:26:44.156384: Warn: Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:26:44.156082+01:00 this is -1605.12 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:26:44.215271: Info: record_status Invertor time is 2024-07-06 13:41:38+00:00 AppDaemon time 2024-07-07 17:26:44.156082+01:00 this is -1605.12 minutes skewed, Predbat may not function correctly, please fix this by updating your inverter or fixing AppDaemon time zone 2024-07-07 17:26:44.216535: Warn: Inverter control auto restart trigger: Clock skew >=10 minutes 2024-07-07 17:26:44.216696: Info: auto_restart not defined in apps.yaml, Predbat can't auto-restart inverter control 2024-07-07 17:26:55.130833: Warn: Set inverter 0 mode Eco via REST failed 2024-07-07 17:26:55.174285: Info: record_status Warn: Inverter 0 REST failed to setBatteryMode

gcoan commented 4 months ago

The message 'appdaemon time' is misleading, it actually refers to the time of the computer that Predbat is running on. I have fixed this in the next PR I will push through.

So what Predbat is reporting is that there is a mismatch between the clock on your Pi running Predbat and the time it is getting back from GivTCP.

So check firstly the clock on the Pi, if this is correct then it points to one of two issues:

  1. The inverter time is wrong. You should be able to sync this from the portal.
  2. GivTCP not being able to communicate reliably with the AIO. It might be a physical/wifi network connection issue or it might be a bug in GivTCP with the AIO
jrwm47 commented 4 months ago

Thanks for your comments and advice.

  1. I think the Pi4/HA time is correct as it agrees with all other clocks around here. The inverter clock was more than 2 days behind and the discrepancy was rapidly increasing.

1.1 I tried resetting it through the GE portal (Time & Date - SEND) but it didn't appear to do anything.

1.2 So next I did a soft reset of the inverter (Restart - SEND) and then restarted GivTCP_Beta and predbat in Monitor mode. Initially everything seemed to be ok but the inverter clock time now appears to be completely stuck and predbat soon stopped updating the plan (SOC% hasn't changed since the restart).

It seems I either have a dead RTC in the inverter or something very screwy with its datetime registers. I don't look forward to persuading GE Support of the problem. I realise this isn't predbat issue but do you know the simplest way to get internal clock readings out of my GE AIO?

  1. The GivTCP problem could be comms but the CTs (ID1, ID2) are hard-wired and LAN mesh wifi signal at the inverter antenna is strong (-61dBm). I suspect a bug in the GivTCP or GE firmware. Again, do you know a simple way to get Energy values out of the AIO?

Cheers

gcoan commented 4 months ago

I'd first of all look at the inverter clock, check that is working properly. If you install the BBC app (search for givenergy on the app store) you can see the raw inverter time and what the inverter is doing: image

Have a look at what is in the GivTCP add-on log. if its failing to communicate with the inverter you should see that happening

Also, have a look at the logbook in Home Assistant, you should see a steady stream of sensors updating every time givtcp polls the inverter. Just a thought, what did you set the self run timer loop to in the givtcp configuration, this is how often the inverter is polled, values between about 15 and 30 seconds are good. Too quick and it can overload the inverter and it can't send messages to the portal