666djb / solarpi

Solar inverter to MQTT bridge for inverter values
13 stars 2 forks source link

Set TOU Charge occasionally not working #4

Closed SimonJBurley closed 6 months ago

SimonJBurley commented 10 months ago

Firstly; many thanks for solarpi. It's working with my SPH 3600 (configured as SPH 3000 in solarpi) and is so much better than using Growatt's mobile app and website. I am on Octopus' Intelligent Go and have set Home Assistant automation to use TOU charging when a cheap slot is active. Sometimes (~5%) the TOU charging fails to become enabled or disabled correctly; leaving the battery not charging when it should be or still in a charging state when it should be load first. I leave the inverter with TOU charging time 1 set to 00:00 - 23:59 and simply set Charge 1 Enable appropriately and press "Set TOU charge" with automation. From Home Assistant's logbook, this seems to run even though, occasionally, the inverter's state is not changed.

From the solarpi journal, I can see a failure this morning

Oct 23 05:33:54 raspberrypi npm[582]: 23/10/2023, 5:33:54 BST Control values stored
Oct 23 05:33:54 raspberrypi npm[582]: 23/10/2023, 5:33:54 BST Publishing data
Oct 23 05:33:55 raspberrypi npm[582]: 23/10/2023, 5:33:55 BST Received Set TOU Charging command
Oct 23 05:34:45 raspberrypi npm[582]: 23/10/2023, 5:34:45 BST Error sending command to inverter:  Transacti>
Oct 23 05:34:45 raspberrypi npm[582]:   name: 'TransactionTimedOutError',
Oct 23 05:34:45 raspberrypi npm[582]:   message: 'Timed out',
Oct 23 05:34:45 raspberrypi npm[582]:   errno: 'ETIMEDOUT'
Oct 23 05:34:45 raspberrypi npm[582]: }

Is this likely cabling or the inverter being difficult?

666djb commented 10 months ago

Hi!

I use Octopus Intelligent and have Home Assistant use TOU Charging when I get a cheap slot too, I do it in a slightly different way to you but it does work with 100% success, however, that is not likely the cause of your problem. I suspect that the Transaction Timed Out Error is more likely a cable problem (I did see those errors in early days of testing before I used a method in my code to ensure that it was not possible to send a command to the inverter while still waiting for a response from the previous).

I wonder whether there are any journal entries immediately prior to 05:33:54 that are relevant?

I could write something that retries a command if a Timed Out Error is received - I'll put that in the list of things to do.

As a stop gap, you could add to your Home Assistant automation a short delay (say 10 seconds) and then repeat the action of pressing the TOU Charge set button.

For completeness, here is my Octopus Intelligent automation:

alias: Octopus Intelligent Slot
description: ""
trigger:
  - platform: state
    entity_id:
      - binary_sensor.octopus_intelligent_slot
    to: "on"
  - platform: state
    entity_id:
      - binary_sensor.octopus_intelligent_slot
    to: "off"
condition: []
action:
  - if:
      - condition: state
        entity_id: binary_sensor.octopus_intelligent_slot
        state: "on"
    then:
      - service: number.set_value
        data:
          value: "0"
        target:
          entity_id: number.solarpi_tou_charge_2_start_hour
      - service: number.set_value
        data:
          value: "0"
        target:
          entity_id: number.solarpi_tou_charge_2_start_minute
      - service: number.set_value
        data:
          value: "23"
        target:
          entity_id: number.solarpi_tou_charge_2_stop_hour
      - service: number.set_value
        data:
          value: "59"
        target:
          entity_id: number.solarpi_tou_charge_2_stop_minute
      - service: switch.turn_on
        data: {}
        target:
          entity_id: switch.solarpi_tou_charge_2_enable
    else:
      - service: switch.turn_off
        data: {}
        target:
          entity_id: switch.solarpi_tou_charge_2_enable
  - service: button.press
    data: {}
    target:
      entity_id: button.solarpi_tou_charge_set
mode: single

This is triggered by either the Intelligent Slot changing to On or Off (this helps deal with that value becoming Unavailable if there is an outage with the Octopus API). Then if the Intelligent Slot is On, it sets up the times from 00:00 to 23:59 on TOU Charge Slot 2 and enables that TOU Charge slot, else (if the Intelligent Slot is Off) it disables that TOU Charge slot. Then, finally it presses the TOU Charge set button (to send the command and write the values to the inverter). (I have a slightly more complex version of this automation that turns off/on a TOU Discharge slot too as I am playing with having any excess charge in the battery exported in the run up to my regular Octopus Intelligent 23:30-05:30 charging slot)

You might be interested in a new entity I have added in the v1.0.8 release - this receives a text value back from SolarPi to report whether a command was successful or not. This too could be used in an automation to do something if there was a problem sending a command. I added this recently when I noticed how the Growatt Inverter behaves if you set overlapping TOU Charge and TOU Discharge time slots, it simply says "nope, you can't do that".

image

SimonJBurley commented 8 months ago

Two months later and I finally have time to reply. Yesterday I removed the cat 5e segment that I joined to the end of the USB RS485 adapter - I purchased the one that you linked - and crimped an RJ45 straight on. I checked the crimp by leaving the green and white wires long so I could check continuity to the RJ45 pins. Even though the continuity was good the comms did not work. I cut the RJ45 off and crimped a new RJ45 on with the green and white wires reversed, checked continuity again and hey presto - it worked! I've only seen one comms error in the 24 hours since, rather than 13 in the 24 hours previous to crimping the RJ45 directly to the RS485 adapter cable. I still suspect that my RS485 adapter isn't working completely correctly so I'll purchase another. I'll upgrade to 1.0.8 today and see if I can add some automation to retry the last command.

SimonJBurley commented 7 months ago

Sadly the errors only increased and I eventually tried another USB RS485 adapter - this one - but still experience the same issue. At this point the issue must lie with the inverter. I think it's super unlikely that the installer would come back to swap it and instead be quite happy to point the finger at third party software. I'm happy to sponsor the development work for the retries on timeout.

666djb commented 7 months ago

That's disappointing. I'll take some photos of my adapter, cable etc. but suspect there'll be no significant difference. There are only three other things I would try myself: 1. Try another PSU for the Pi (mine was fine with any including a USB outlet on a mains socket, a regular USB phone charger and plugged into the USB port on the bottom of the inverter) 2. Power off and on the inverter "just in case" - if you do this follow the instructions! 3. Try another Pi if you have one or can borrow one.

I'll build a new branch of the code that retries upon error. Can't guarantee exactly when, but if it rains at the weekend it'll give me something interesting to do.

666djb commented 7 months ago

Hi! I've just pushed a new branch named beta (https://github.com/666djb/solarpi/tree/beta)

I've added code that should send each command to the inverter up to 3 times if an USB/serial error occurs. It prints a few more debug messages which on my setup (without errors) look like the following when I press "Set TOU Charge" in Home Assistant.

Jan 21 14:00:26 solar npm[24643]: 21/01/2024, 14:00:26 GMT Received Set TOU Charging command Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() attempt number 1 Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() acquiring mutex Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() acquired mutex Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() modbusClient.writeRegisters() successful Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() released mutex Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() success Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() attempt number 1 Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() acquiring mutex Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() acquired mutex Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() modbusClient.writeRegisters() successful Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() released mutex Jan 21 14:00:28 solar npm[24643]: 21/01/2024, 14:00:28 GMT DEBUG: writeRegisters() success

(When we set TOU charging values, two sets of data are written to the inverter, hence why the above shows the same sequence twice)

You can change to the beta branch by doing something like the following on your Pi in your download folder: "git fetch" "git checkout beta" and then look at the readme.md file (using a command like: "more readme.md") and check the first line says:

SolarPi v1.0.9 beta 2

and then run ". ./update.sh"

So far I've not tried to cause any errors to fully test this code, but will leave it running on my Pi to at least make sure it doesn't cause problems when there are no errors! It would be useful to see what output you get when you try it.

You can switch back to the normal version by doing: "git checkout public" then ". ./update.sh"

SimonJBurley commented 7 months ago

I'm happy to say I've not seen Set TOU Charging failure since I updated to 1.0.9 beta 2 on the 21st. Although I still see data collection errors, eg

Jan 31 15:07:08 raspberrypi npm[628171]: 31/01/2024, 15:07:08 GMT Publishing data
Jan 31 15:08:57 raspberrypi npm[628171]: 31/01/2024, 15:08:57 GMT Error reading inverter data: TransactionTimedOutError {
Jan 31 15:08:57 raspberrypi npm[628171]:   name: 'TransactionTimedOutError',
Jan 31 15:08:57 raspberrypi npm[628171]:   message: 'Timed out',
Jan 31 15:08:57 raspberrypi npm[628171]:   errno: 'ETIMEDOUT'
Jan 31 15:08:57 raspberrypi npm[628171]: }
Jan 31 15:08:57 raspberrypi npm[628171]: 31/01/2024, 15:08:57 GMT Publishing data

I did see one anomaly that stood out, only because inverterClient.getData() is async and the timeout occurred while writeRegisters() held the mutex:

Jan 25 05:31:31 raspberrypi npm[628171]: 25/01/2024, 5:31:31 GMT Publishing data
Jan 25 05:33:15 raspberrypi npm[628171]: 25/01/2024, 5:33:15 GMT Control values stored
Jan 25 05:33:15 raspberrypi npm[628171]: 25/01/2024, 5:33:15 GMT Control values stored
Jan 25 05:33:15 raspberrypi npm[628171]: 25/01/2024, 5:33:15 GMT Control values stored
Jan 25 05:33:15 raspberrypi npm[628171]: 25/01/2024, 5:33:15 GMT Control values stored
Jan 25 05:33:15 raspberrypi npm[628171]: 25/01/2024, 5:33:15 GMT Control values stored
Jan 25 05:33:15 raspberrypi npm[628171]: 25/01/2024, 5:33:15 GMT Received Set TOU Discharging command
Jan 25 05:33:15 raspberrypi npm[628171]: 25/01/2024, 5:33:15 GMT DEBUG: writeRegisters() attempt number 1
Jan 25 05:33:15 raspberrypi npm[628171]: 25/01/2024, 5:33:15 GMT DEBUG: writeRegisters() acquiring mutex
Jan 25 05:33:16 raspberrypi npm[628171]: 25/01/2024, 5:33:16 GMT Control values stored
Jan 25 05:33:16 raspberrypi npm[628171]: 25/01/2024, 5:33:16 GMT Received Set TOU Charging command
Jan 25 05:33:16 raspberrypi npm[628171]: 25/01/2024, 5:33:16 GMT DEBUG: writeRegisters() attempt number 1
Jan 25 05:33:16 raspberrypi npm[628171]: 25/01/2024, 5:33:16 GMT DEBUG: writeRegisters() acquiring mutex
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() acquired mutex
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT Error reading inverter data: TransactionTimedOutError {
Jan 25 05:33:21 raspberrypi npm[628171]:   name: 'TransactionTimedOutError',
Jan 25 05:33:21 raspberrypi npm[628171]:   message: 'Timed out',
Jan 25 05:33:21 raspberrypi npm[628171]:   errno: 'ETIMEDOUT'
Jan 25 05:33:21 raspberrypi npm[628171]: }
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT Publishing data
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() modbusClient.writeRegisters() successful
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() released mutex
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() success
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() attempt number 1
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() acquiring mutex
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() acquired mutex
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() modbusClient.writeRegisters() successful
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() released mutex
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() success
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() attempt number 1
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() acquiring mutex
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() acquired mutex
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() modbusClient.writeRegisters() successful
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() released mutex
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() success
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() acquired mutex
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT Command sent to inverter
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() modbusClient.writeRegisters() successful
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() released mutex
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT DEBUG: writeRegisters() success
Jan 25 05:33:21 raspberrypi npm[628171]: 25/01/2024, 5:33:21 GMT Command sent to inverter
Jan 25 05:33:31 raspberrypi npm[628171]: 25/01/2024, 5:33:31 GMT Publishing data
Jan 25 05:34:31 raspberrypi npm[628171]: 25/01/2024, 5:34:31 GMT Publishing data

I'm using the official Pi power supply and I've tried with and without the RS485 to inverter ground connected and disconnected with the same result. I could certainly try to power the Pi from the Growatt, but I imagine this will require disconnecting the wifi dongle. Do you think this is worth a try?

666djb commented 7 months ago

Hi!

I've now added code (Beta 3) to retry reads from the inverter as well as writes to the inverter. In doing so, I've simplified how this is done and if you give it a go, the debug messages are fewer and slightly different.

I suspect your anomaly above is related to the code running asynchronously and that the first and second Set TOU Discharging commands overlapped - the sequence of acquiring/releasing the mutex is impossible to tell from the debug log.

If you are using the official Pi PSU, then that is a good as you can get and practically rules that out as a problem (the internet suggests running from old mobile phone chargers can cause problems as some provide insufficient current at times).

SimonJBurley commented 6 months ago

I'm going to close this as I've not had an issue since deploying beta 3. Thanks for making these changes.

666djb commented 6 months ago

Thanks for letting me know. I'll fold the changes in to the main version with less logging detail.