springfall2008 / batpred

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

Moving from Hold charging to discharging gets stuck #1191

Open dochtie opened 3 months ago

dochtie commented 3 months ago

Describe the bug If predbat is on hold charging it sets ‘pause discharge’ via GivTCP. When it moves to the next slot if force discharging is planned it does not unset pause discharge and so the battery doesn’t discharge.

I noticed predbat was in force discharge mode (to 4%) but the battery was not discharging. I disabled pause discharge which was still set and the battery began discharging as expected.

Expected behavior Remove the pause discharge (givTCP) when attempting to discharge.

Predbat version

7.22.3

Should be easy to reproduce but if you need log file please let me know.

gcoan commented 3 months ago

I have intermittently seen the pause discharge being set on my inverter when it should be force discharging but couldn't identify a pattern of why it happened.

I think it only happens on one inverter as well so I was thinking it might be an error changing the battery pause mode that predbat didn't pick up on, and when it next runs it doesn't check pause mode again.

I was waiting for a reoccurrence to verify this hypothesis. Can you check the givtcp log to see if there are any errors in it?

dochtie commented 3 months ago

Hi,

here are GivTCP logs for the time in question. The battery pause disable was me manually changing it. Predbat did not attempt (according to GivTCP).

it set export and discharge at 8.31 but didn’t remove the pause mode it had set at 8.28.

2024-06-08 08:28:09,468 - write - [INFO] - Setting Battery Pause Mode to: PauseDischarge 2024-06-08 08:28:16,657 - write - [INFO] - Setting Battery Pause Mode to PauseDischarge was a success 2024-06-08 08:28:22,437 - write - [INFO] - Setting shallow charge 30 was a success 2024-06-08 08:30:32,163 - write - [INFO] - Setting Charge Slot 1 was a success 2024-06-08 08:30:46,604 - write - [INFO] - Setting Charge Enable was a success 2024-06-08 08:30:58,305 - write - [INFO] - Setting Discharge Slot 1 was a success 2024-06-08 08:31:11,486 - write - [INFO] - Setting export mode was a success 2024-06-08 08:31:14,265 - write - [INFO] - Enabling Discharge was a success 2024-06-08 08:31:29,986 - write - [INFO] - Setting shallow charge 4 was a success 2024-06-08 08:31:40,734 - write - [INFO] - Setting Charge Target 24 failed: (<class 'AssertionError'>, AssertionError('Unexpected response from remote end: Modbus Error: [Input/Output] Modbus Error: [Invalid Message] No response received, expected at least 44 bytes (0 received)'), <traceback object at 0xffffb3f14b00>) 2024-06-08 08:31:55,257 - write - [INFO] - Setting Charge Target 24 was a success 2024-06-08 08:32:12,378 - write - [INFO] - Setting Charge Target 24 was a success 2024-06-08 08:37:19,170 - write - [INFO] - Setting Battery Pause Mode to: Disabled 2024-06-08 08:37:21,991 - write - [INFO] - Setting Battery Pause Mode to Disabled was a success

gcoan commented 3 months ago

Thanks, so shows it was a 'command not sent by predbat' rather than a 'command sent but not acted upon' which was my hypothesis based on one inverter being left on battery pause=Discharge Paused and the other on Disabled.

gcoan commented 3 months ago

Same issue happened to me today. 13:25 predbat went into Hold Charging setting Battery Pause Mode to 'Pause Discharge', and at the 13:30 run when it changed to status Discharging, the Pause Discharge wasn't removed so despite the inverter mode being set to Timed Export, the battery didn't start discharging

Predbat status: image

Inverter mode, showing Timed Export was set at 13:31: image

Battery Pause Mode, as you can see it wasn't changed from the Pause Discharge set at 13:20 until I manually changed it at 13:53: image

Battery power graph showing inverters didn't start discharging until 13:53 when I manually changed the pause mode: image

Inverter logs, show battery pause mode wasn't attempted to be reset around 13:30: log_inv_1.log

log_inv_2.log

Predbat logfile: appdaemon.log.txt

springfall2008 commented 3 months ago

Well the good news is I think the problem was fairly trivial (a missed line) and I merged the fixed to 'main'

If you want to try it out then please upgrade to v7.22.5 first, then update to 'main' afterwards (this is important). The other changes on main split up the Predbat source code and store the settings locally in a .json file rather than just depending on HA state.

gcoan commented 3 months ago

Thanks Trefor I thought it probably was a trivial fix.

I upgraded to 7.22.5 and then main (8.0.0) and it's running fine, no unexpected failures.

The split of predbat into a number of sub files does give a bunch of warnings when appdaemon initialises itself:

2024-06-09 20:56:55.860510 WARNING AppDaemon: No app description found for: /homeassistant/appdaemon/apps/batpred/prediction.py - ignoring 2024-06-09 20:56:55.862335 WARNING AppDaemon: No app description found for: /homeassistant/appdaemon/apps/batpred/ha.py - ignoring 2024-06-09 20:56:55.864424 WARNING AppDaemon: No app description found for: /homeassistant/appdaemon/apps/batpred/utils.py - ignoring 2024-06-09 20:56:55.871528 WARNING AppDaemon: No app description found for: /homeassistant/appdaemon/apps/batpred/config.py - ignoring 2024-06-09 20:56:55.872302 INFO AppDaemon: Reloading Module: /homeassistant/appdaemon/apps/batpred/predbat.py 2024-06-09 20:56:56.102569 WARNING AppDaemon: No app description found for: /homeassistant/appdaemon/apps/batpred/download.py - ignoring 2024-06-09 20:56:56.103975 WARNING AppDaemon: No app description found for: /homeassistant/appdaemon/apps/batpred/inverter.py - ignoring 2024-06-09 20:56:56.104945 INFO AppDaemon: Loading app pred_bat using class PredBat from module predbat 2024-06-09 20:56:56.107753 INFO AppDaemon: Calling initialize() for pred_bat

But other than that I couldn't see any problems with the run.

There's a hold charge planned for tomorrow afternoon so I'll look to see if its executed and that the fix works

gcoan commented 3 months ago

We had a number of hold charges today and I don't think the release on main is working perfectly yet...

Had a look just now and found that inverter 1 was stuck on Pause Discharge but inverter 2 battery pause mode was Disabled.

GivTCP logs, can see Inv1 was set to Pause Discharging at 12:00 and never changed after that, but Inv 2 set to Pause Discharging at 12:01 but then reset to Disabled at 12:16

log_inv_1.log log_inv_2.log

Inv 1 battery pause mode: image

Inv 2 battery pause mode has been set and reset many more times: image

Predbat status, shows Freeze charging was set at 12:01 but then Charging at 12:17 (which should have cancelled both Pause Discharging's), Hold Charging at 12:21, Charging again at 12:37 (ditto). The battery pause mode wasn't cancelled on inverter 1 on any of these subsequent status changes to Charging: image

Appdaemon log: appdaemon.log

dochtie commented 3 months ago

Thanks for doing the heavy lifting here. Bug still present for me too.

springfall2008 commented 1 month ago

Is this still an issue?