search

britkat1980 / giv_tcp

TCP connection (from inverter) and MQTT implementation
71 stars 32 forks source link

No attribute 'serial_number' gen 1 hybrid #153

Open gcoan opened 7 months ago

gcoan commented 7 months ago

I have two gen 1 hybrids. One with a battery (inverter 2) and one without (inverter 1).

Both were working fine this morning and then stopped receiving updates from inverter 2 in givtcp.

It didn't correct itself so I restarted givtcp, still same issue. Restarted mosquitto, givtcp again, the inverter, all the same, not getting any updates from inverter 2 but inverter 1 is polling fine

In the logfile, same error as #145 which was fixed in 2,4.2 and I'm running givtcp 2.4.3 and it was working fine, and then stopped working

023-11-29 11:21:32,911 - Inv2 - mqtt_client -  [CRITICAL] - Connecting to MQTT broker for control- core-mosquitto
2023-11-29 11:21:36,623 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% and no previous value so setting to 1%
2023-11-29 11:21:36,627 - Inv1 - read        -  [CRITICAL] - First time running so saving AC Charge status
2023-11-29 11:21:36,631 - Inv1 - read        -  [CRITICAL] - Publishing Home Assistant Discovery messages
2023-11-29 11:21:42,967 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:22:04,214 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:22:25,624 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:22:41,788 - Inv2 - read        -  [ERROR   ] - 10 failed inverter reads in a row so removing regCache to force update...
2023-11-29 11:23:08,000 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:23:13,103 - Inv2 - mqtt_client -  [ERROR   ] - No serial_number found in MQTT queue. MQTT Control not available.
Traceback (most recent call last):
  File "/app/GivTCP_2/mqtt_client.py", line 402, in <module>
    client.loop_forever()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 1756, in loop_forever
    rc = self._loop(timeout)
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 1164, in _loop
    rc = self.loop_read()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 1556, in loop_read
    rc = self._packet_read()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 2439, in _packet_read
    rc = self._packet_handle()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 3039, in _packet_handle
    return self._handle_connack()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 3138, in _handle_connack
    on_connect(
  File "/app/GivTCP_2/mqtt_client.py", line 386, in on_connect
    client.subscribe(MQTT_Topic+"/control/"+GiV_Settings.serial_number+"/#")
AttributeError: type object 'GiV_Settings' has no attribute 'serial_number'
2023-11-29 11:23:29,495 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:23:49,688 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:24:09,957 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:24:30,264 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:24:50,766 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:25:10,820 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:25:31,042 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:25:51,193 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:26:11,328 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:26:19,330 - Inv2 - read        -  [ERROR   ] - 10 failed inverter reads in a row so removing regCache to force update...
2023-11-29 11:26:31,731 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:26:52,198 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 11:27:12,348 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value

(ignore fail to read inv1 battery, that's a separate issue I will log, but not critical to this) l I don't see any data for inverter 2 in MQTT Explorer image

Inverter is online OK, I can see it in the Inverter iOS app and the GivEnergy app, both remote and local mode

debug log:

2023-11-29 11:37:05,134 - Inv1 - mqtt        -  [DEBUG   ] - In wait loop
2023-11-29 11:37:05,320 - Inv1 - mqtt        -  [DEBUG   ] - connected OK Returned code=0
2023-11-29 11:37:05,337 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Last_Updated_Time
2023-11-29 11:37:05,338 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/status
2023-11-29 11:37:05,339 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Time_Since_Last_Update
2023-11-29 11:37:05,341 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/GivTCP_Version
2023-11-29 11:37:05,343 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Power
2023-11-29 11:37:05,346 - Inv1 - mqtt        -  [DEBUG   ] - Prepping Power for publishing
2023-11-29 11:37:05,346 - Inv1 - mqtt        -  [DEBUG   ] - Prepping Flows for publishing
2023-11-29 11:37:05,350 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Invertor_Details
2023-11-29 11:37:05,352 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Energy
2023-11-29 11:37:05,353 - Inv1 - mqtt        -  [DEBUG   ] - Prepping Today for publishing
2023-11-29 11:37:05,355 - Inv1 - mqtt        -  [DEBUG   ] - Prepping Total for publishing
2023-11-29 11:37:05,359 - Inv1 - mqtt        -  [DEBUG   ] - Prepping Rates for publishing
2023-11-29 11:37:05,363 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Timeslots
2023-11-29 11:37:05,363 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Control
2023-11-29 11:37:05,364 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Battery_Details
2023-11-29 11:37:05,364 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/raw
2023-11-29 11:37:05,365 - Inv1 - mqtt        -  [DEBUG   ] - Prepping invertor for publishing
2023-11-29 11:37:17,791 - Inv2 - read        -  [DEBUG   ] - ----------------------------Starting----------------------------
2023-11-29 11:37:17,792 - Inv2 - read        -  [DEBUG   ] - Getting All Registers
2023-11-29 11:37:17,792 - Inv2 - read        -  [DEBUG   ] - Connecting to: 192.168.1.159
2023-11-29 11:37:17,793 - Inv2 - queue       -  [DEBUG   ] - Pushed job 3be1084d-899a-47c0-80cf-6245d16fa063 into GivTCP_2
2023-11-29 11:37:18,073 - Inv2 - sync        -  [DEBUG   ] - Connection to Modbus server established. Socket ('192.168.1.79', 32893)
2023-11-29 11:37:18,075 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - IDLE
2023-11-29 11:37:18,076 - Inv2 - transaction -  [DEBUG   ] - Running transaction 1
2023-11-29 11:37:18,077 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:37:18,323 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:37:18,326 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:37:18,326 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 1
2023-11-29 11:37:18,326 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:37:18,827 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:37:18,828 - Inv2 - transaction -  [DEBUG   ] - Running transaction 2
2023-11-29 11:37:18,829 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:37:19,059 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:37:19,060 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:37:19,061 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 2
2023-11-29 11:37:19,061 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:37:19,564 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:37:19,565 - Inv2 - transaction -  [DEBUG   ] - Running transaction 3
2023-11-29 11:37:19,565 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:37:19,812 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:37:19,813 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:37:19,814 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 3
2023-11-29 11:37:19,814 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:37:20,322 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:37:20,323 - Inv2 - transaction -  [DEBUG   ] - Running transaction 4
2023-11-29 11:37:20,324 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:37:20,413 - Inv1 - read        -  [DEBUG   ] - ----------------------------Starting----------------------------
2023-11-29 11:37:20,418 - Inv1 - read        -  [DEBUG   ] - Getting All Registers
2023-11-29 11:37:20,419 - Inv1 - read        -  [DEBUG   ] - Connecting to: 192.168.1.160
2023-11-29 11:37:20,425 - Inv1 - queue       -  [DEBUG   ] - Pushed job d86b7f0f-450a-415c-999e-f397c62846a5 into GivTCP_1
2023-11-29 11:37:20,575 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:37:20,576 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:37:20,577 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 4
2023-11-29 11:37:20,577 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:37:20,726 - Inv1 - sync        -  [DEBUG   ] - Connection to Modbus server established. Socket ('192.168.1.79', 44147)
2023-11-29 11:37:20,731 - Inv1 - transaction -  [DEBUG   ] - Current transaction state - IDLE
2023-11-29 11:37:20,731 - Inv1 - transaction -  [DEBUG   ] - Running transaction 1
2023-11-29 11:37:20,731 - Inv1 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:37:20,974 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:37:20,975 - Inv1 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:37:20,975 - Inv1 - transaction -  [DEBUG   ] - Adding transaction 1
2023-11-29 11:37:20,976 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:37:21,080 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:37:21,080 - Inv2 - transaction -  [DEBUG   ] - Running transaction 5
2023-11-29 11:37:21,081 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:37:21,319 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:37:21,321 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:37:21,321 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 5
2023-11-29 11:37:21,321 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:37:21,477 - Inv1 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:37:21,477 - Inv1 - transaction -  [DEBUG   ] - Running transaction 2
2023-11-29 11:37:21,477 - Inv1 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:37:21,711 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:37:21,713 - Inv1 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:37:21,714 - Inv1 - transaction -  [DEBUG   ] - Adding transaction 2
2023-11-29 11:37:21,715 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:37:21,822 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:37:21,823 - Inv2 - transaction -  [DEBUG   ] - Running transaction 6
2023-11-29 11:37:21,823 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:37:22,070 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:37:22,071 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:37:22,072 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 6
2023-11-29 11:37:22,072 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:37:22,221 - Inv1 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:37:22,226 - Inv1 - transaction -  [DEBUG   ] - Running transaction 3
2023-11-29 11:37:22,230 - Inv1 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:37:22,471 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:37:22,471 - Inv1 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:37:22,472 - Inv1 - transaction -  [DEBUG   ] - Adding transaction 3
2023-11-29 11:37:22,473 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:37:22,671 - Inv2 - read        -  [ERROR   ] - 10 failed inverter reads in a row so removing regCache to force update...
2023-11-29 11:37:22,998 - Inv1 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:37:22,999 - Inv1 - transaction -  [DEBUG   ] - Running transaction 4
2023-11-29 11:37:23,000 - Inv1 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:37:23,241 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:37:23,242 - Inv1 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:37:23,242 - Inv1 - transaction -  [DEBUG   ] - Adding transaction 4
2023-11-29 11:37:23,242 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
...
2023-11-29 11:38:57,651 - Inv2 - read        -  [DEBUG   ] - ----------------------------Starting----------------------------
2023-11-29 11:38:57,652 - Inv2 - read        -  [DEBUG   ] - Getting All Registers
2023-11-29 11:38:57,653 - Inv2 - read        -  [DEBUG   ] - Connecting to: 192.168.1.159
2023-11-29 11:38:57,654 - Inv2 - queue       -  [DEBUG   ] - Pushed job 230c409b-da8d-44bd-b0b9-34111de4d906 into GivTCP_2
2023-11-29 11:38:57,947 - Inv2 - sync        -  [DEBUG   ] - Connection to Modbus server established. Socket ('192.168.1.79', 46721)
2023-11-29 11:38:57,948 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - IDLE
2023-11-29 11:38:57,948 - Inv2 - transaction -  [DEBUG   ] - Running transaction 1
2023-11-29 11:38:57,949 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:38:58,201 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:38:58,203 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:38:58,203 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 1
2023-11-29 11:38:58,204 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:38:58,705 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:38:58,706 - Inv2 - transaction -  [DEBUG   ] - Running transaction 2
2023-11-29 11:38:58,706 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:38:58,941 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:38:58,942 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:38:58,943 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 2
2023-11-29 11:38:58,943 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:38:59,445 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:38:59,449 - Inv2 - transaction -  [DEBUG   ] - Running transaction 3
2023-11-29 11:38:59,450 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:38:59,699 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:38:59,700 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:38:59,701 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 3
2023-11-29 11:38:59,701 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:39:00,202 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:39:00,202 - Inv2 - transaction -  [DEBUG   ] - Running transaction 4
2023-11-29 11:39:00,203 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:39:00,454 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:39:00,454 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:39:00,454 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 4
2023-11-29 11:39:00,459 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:39:00,961 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:39:00,961 - Inv2 - transaction -  [DEBUG   ] - Running transaction 5
2023-11-29 11:39:00,962 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:39:01,202 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:39:01,202 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:39:01,203 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 5
2023-11-29 11:39:01,203 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:39:01,699 - Inv1 - read        -  [DEBUG   ] - ----------------------------Starting----------------------------
2023-11-29 11:39:01,700 - Inv1 - read        -  [DEBUG   ] - Getting All Registers
2023-11-29 11:39:01,700 - Inv1 - read        -  [DEBUG   ] - Connecting to: 192.168.1.160
2023-11-29 11:39:01,700 - Inv1 - queue       -  [DEBUG   ] - Pushed job 384f823a-ebc7-4baf-8c87-bc19f5c03177 into GivTCP_1
...
2023-11-29 11:39:05,893 - Inv1 - read        -  [DEBUG   ] - Converting datetime to publish safe string
2023-11-29 11:39:05,893 - Inv1 - read        -  [DEBUG   ] - Converting Tuple to multiple publish safe strings
2023-11-29 11:39:05,893 - Inv1 - read        -  [DEBUG   ] - Converting Tuple to multiple publish safe strings
2023-11-29 11:39:05,893 - Inv1 - read        -  [DEBUG   ] - Converting Timeslots to publish safe string
2023-11-29 11:39:05,893 - Inv1 - read        -  [DEBUG   ] - Converting Timeslots to publish safe string
2023-11-29 11:39:05,893 - Inv1 - read        -  [DEBUG   ] - Converting Timeslots to publish safe string
2023-11-29 11:39:05,894 - Inv1 - read        -  [DEBUG   ] - Converting Tuple to multiple publish safe strings
2023-11-29 11:39:05,901 - Inv1 - read        -  [DEBUG   ] - Dealt with invertor
2023-11-29 11:39:05,902 - Inv1 - read        -  [DEBUG   ] - Dealt with raw
2023-11-29 11:39:05,902 - Inv1 - read        -  [DEBUG   ] - Publish all to MQTT
2023-11-29 11:39:05,902 - Inv1 - mqtt        -  [DEBUG   ] - Connecting to broker: core-mosquitto
2023-11-29 11:39:05,905 - Inv1 - mqtt        -  [DEBUG   ] - In wait loop
2023-11-29 11:39:06,164 - Inv1 - mqtt        -  [DEBUG   ] - In wait loop
2023-11-29 11:39:06,369 - Inv1 - mqtt        -  [DEBUG   ] - In wait loop
2023-11-29 11:39:06,571 - Inv1 - mqtt        -  [DEBUG   ] - In wait loop
2023-11-29 11:39:06,772 - Inv1 - mqtt        -  [DEBUG   ] - In wait loop
2023-11-29 11:39:06,922 - Inv1 - mqtt        -  [DEBUG   ] - connected OK Returned code=0
2023-11-29 11:39:07,041 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Last_Updated_Time
2023-11-29 11:39:07,047 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/status
2023-11-29 11:39:07,048 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Time_Since_Last_Update
2023-11-29 11:39:07,048 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/GivTCP_Version
2023-11-29 11:39:07,049 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Power
2023-11-29 11:39:07,049 - Inv1 - mqtt        -  [DEBUG   ] - Prepping Power for publishing
2023-11-29 11:39:07,049 - Inv1 - mqtt        -  [DEBUG   ] - Prepping Flows for publishing
2023-11-29 11:39:07,063 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Invertor_Details
2023-11-29 11:39:07,064 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Energy
2023-11-29 11:39:07,064 - Inv1 - mqtt        -  [DEBUG   ] - Prepping Today for publishing
2023-11-29 11:39:07,064 - Inv1 - mqtt        -  [DEBUG   ] - Prepping Total for publishing
2023-11-29 11:39:07,065 - Inv1 - mqtt        -  [DEBUG   ] - Prepping Rates for publishing
2023-11-29 11:39:07,066 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Timeslots
2023-11-29 11:39:07,068 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Control
2023-11-29 11:39:07,070 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/Battery_Details
2023-11-29 11:39:07,082 - Inv1 - mqtt        -  [DEBUG   ] - Publishing: GivEnergy/SD2237G182/raw
2023-11-29 11:39:07,085 - Inv1 - mqtt        -  [DEBUG   ] - Prepping invertor for publishing
2023-11-29 11:39:17,574 - Inv2 - read        -  [DEBUG   ] - ----------------------------Starting----------------------------
2023-11-29 11:39:17,576 - Inv2 - read        -  [DEBUG   ] - Getting All Registers
2023-11-29 11:39:17,576 - Inv2 - read        -  [DEBUG   ] - Connecting to: 192.168.1.159
2023-11-29 11:39:17,577 - Inv2 - queue       -  [DEBUG   ] - Pushed job 4ed26293-6214-49d0-a883-f5a3abf30157 into GivTCP_2
2023-11-29 11:39:17,881 - Inv2 - sync        -  [DEBUG   ] - Connection to Modbus server established. Socket ('192.168.1.79', 39271)
2023-11-29 11:39:17,887 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - IDLE
2023-11-29 11:39:17,889 - Inv2 - transaction -  [DEBUG   ] - Running transaction 1
2023-11-29 11:39:17,889 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:39:18,136 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:39:18,137 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:39:18,137 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 1
2023-11-29 11:39:18,137 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:39:18,639 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:39:18,642 - Inv2 - transaction -  [DEBUG   ] - Running transaction 2
2023-11-29 11:39:18,643 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:39:18,876 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:39:18,876 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:39:18,877 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 2
2023-11-29 11:39:18,877 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:39:19,378 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:39:19,379 - Inv2 - transaction -  [DEBUG   ] - Running transaction 3
2023-11-29 11:39:19,380 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:39:19,622 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:39:19,623 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:39:19,624 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 3
2023-11-29 11:39:19,625 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:39:20,127 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:39:20,127 - Inv2 - transaction -  [DEBUG   ] - Running transaction 4
2023-11-29 11:39:20,127 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:39:20,372 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:39:20,375 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:39:20,375 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 4
2023-11-29 11:39:20,384 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:39:20,888 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:39:20,888 - Inv2 - transaction -  [DEBUG   ] - Running transaction 5
2023-11-29 11:39:20,888 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:39:21,134 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:39:21,135 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:39:21,136 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 5
2023-11-29 11:39:21,138 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:39:21,732 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:39:21,733 - Inv2 - transaction -  [DEBUG   ] - Running transaction 6
2023-11-29 11:39:21,735 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:39:21,973 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:39:21,974 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:39:21,974 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 6
2023-11-29 11:39:21,975 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:39:22,124 - Inv1 - read        -  [DEBUG   ] - ----------------------------Starting----------------------------
2023-11-29 11:39:22,124 - Inv1 - read        -  [DEBUG   ] - Getting All Registers
2023-11-29 11:39:22,124 - Inv1 - read        -  [DEBUG   ] - Connecting to: 192.168.1.160
2023-11-29 11:39:22,125 - Inv1 - queue       -  [DEBUG   ] - Pushed job b72fc41b-4464-41c2-a53b-7ff56cf7a202 into GivTCP_1
2023-11-29 11:39:22,389 - Inv1 - sync        -  [DEBUG   ] - Connection to Modbus server established. Socket ('192.168.1.79', 45821)
2023-11-29 11:39:22,390 - Inv1 - transaction -  [DEBUG   ] - Current transaction state - IDLE
2023-11-29 11:39:22,392 - Inv1 - transaction -  [DEBUG   ] - Running transaction 1
2023-11-29 11:39:22,393 - Inv1 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:39:22,640 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:39:22,641 - Inv1 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:39:22,641 - Inv1 - transaction -  [DEBUG   ] - Adding transaction 1
2023-11-29 11:39:22,643 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:39:23,145 - Inv1 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:39:23,147 - Inv1 - transaction -  [DEBUG   ] - Running transaction 2
2023-11-29 11:39:23,147 - Inv1 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:39:23,384 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:39:23,385 - Inv1 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:39:23,386 - Inv1 - transaction -  [DEBUG   ] - Adding transaction 2
2023-11-29 11:39:23,387 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
...
2023-11-29 11:40:57,444 - Inv2 - read        -  [DEBUG   ] - ----------------------------Starting----------------------------
2023-11-29 11:40:57,445 - Inv2 - read        -  [DEBUG   ] - Getting All Registers
2023-11-29 11:40:57,446 - Inv2 - read        -  [DEBUG   ] - Connecting to: 192.168.1.159
2023-11-29 11:40:57,448 - Inv2 - queue       -  [DEBUG   ] - Pushed job c7b54e47-ecec-4a43-8cad-f343c80cf59e into GivTCP_2
2023-11-29 11:40:57,657 - Inv2 - sync        -  [DEBUG   ] - Connection to Modbus server established. Socket ('192.168.1.79', 33237)
2023-11-29 11:40:57,666 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - IDLE
2023-11-29 11:40:57,671 - Inv2 - transaction -  [DEBUG   ] - Running transaction 1
2023-11-29 11:40:57,672 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:40:57,913 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:40:57,914 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:40:57,916 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 1
2023-11-29 11:40:57,921 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:40:58,429 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:40:58,430 - Inv2 - transaction -  [DEBUG   ] - Running transaction 2
2023-11-29 11:40:58,430 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:40:58,674 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:40:58,692 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:40:58,695 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 2
2023-11-29 11:40:58,696 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:40:59,222 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:40:59,223 - Inv2 - transaction -  [DEBUG   ] - Running transaction 3
2023-11-29 11:40:59,224 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:40:59,462 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:40:59,464 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:40:59,464 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 3
2023-11-29 11:40:59,465 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:40:59,966 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:40:59,967 - Inv2 - transaction -  [DEBUG   ] - Running transaction 4
2023-11-29 11:40:59,969 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:41:00,212 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:41:00,216 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:41:00,217 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 4
2023-11-29 11:41:00,218 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:41:00,721 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:41:00,722 - Inv2 - transaction -  [DEBUG   ] - Running transaction 5
2023-11-29 11:41:00,724 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:41:00,973 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:41:00,975 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:41:00,976 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 5
2023-11-29 11:41:00,978 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:41:01,480 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:41:01,480 - Inv2 - transaction -  [DEBUG   ] - Running transaction 6
2023-11-29 11:41:01,481 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:41:01,722 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:41:01,723 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:41:01,728 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 6
2023-11-29 11:41:01,728 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:41:02,271 - Inv2 - read        -  [ERROR   ] - 10 failed inverter reads in a row so removing regCache to force

Hard to tell from the log but it looks like it sends a request to the inverter 2, waits for a reply, gets a reply and processes it, marks as transaction complete but then decides 10 failed inverter reads.

Only thing I can think of is to physically power the inverter off and on again and see if that makes a difference. I have restarted it via the portal twice

gcoan commented 7 months ago

Nope, didn't work.

Physically restarted the inverter, it is online in the inverter and givenergy apps, but same errors in the givtcp logs

2023-11-29 11:52:27,194 - Inv2 - read        -  [DEBUG   ] - ----------------------------Starting----------------------------
2023-11-29 11:52:27,194 - Inv2 - read        -  [DEBUG   ] - Getting All Registers
2023-11-29 11:52:27,194 - Inv2 - read        -  [DEBUG   ] - Connecting to: 192.168.1.159
2023-11-29 11:52:27,195 - Inv2 - queue       -  [DEBUG   ] - Pushed job dc782af5-451c-44d3-adb5-a2660ba95b14 into GivTCP_2
2023-11-29 11:52:27,515 - Inv2 - sync        -  [DEBUG   ] - Connection to Modbus server established. Socket ('192.168.1.79', 39333)
2023-11-29 11:52:27,516 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - IDLE
2023-11-29 11:52:27,517 - Inv2 - transaction -  [DEBUG   ] - Running transaction 1
2023-11-29 11:52:27,520 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:52:27,781 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:52:27,781 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:52:27,782 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 1
2023-11-29 11:52:27,782 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:52:28,339 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:52:28,340 - Inv2 - transaction -  [DEBUG   ] - Running transaction 2
2023-11-29 11:52:28,340 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:52:28,601 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:52:28,616 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:52:28,623 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 2
2023-11-29 11:52:28,623 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:52:29,125 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:52:29,125 - Inv2 - transaction -  [DEBUG   ] - Running transaction 3
2023-11-29 11:52:29,126 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:52:29,364 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:52:29,365 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:52:29,367 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 3
2023-11-29 11:52:29,367 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:52:29,874 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:52:29,876 - Inv2 - transaction -  [DEBUG   ] - Running transaction 4
2023-11-29 11:52:29,877 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:52:30,161 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:52:30,163 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:52:30,166 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 4
2023-11-29 11:52:30,166 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:52:30,670 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:52:30,671 - Inv2 - transaction -  [DEBUG   ] - Running transaction 5
2023-11-29 11:52:30,673 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:52:30,912 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:52:30,914 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:52:30,914 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 5
2023-11-29 11:52:30,914 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:52:31,415 - Inv2 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-11-29 11:52:31,420 - Inv2 - transaction -  [DEBUG   ] - Running transaction 6
2023-11-29 11:52:31,420 - Inv2 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-11-29 11:52:31,682 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-11-29 11:52:31,685 - Inv2 - payload     -  [DEBUG   ] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x8a']
2023-11-29 11:52:31,687 - Inv2 - transaction -  [DEBUG   ] - Adding transaction 6
2023-11-29 11:52:31,687 - Inv2 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-11-29 11:52:32,229 - Inv2 - read        -  [ERROR   ] - 10 failed inverter reads in a row so removing regCache to force update...
gcoan commented 7 months ago

Another roll of the dice, shutdown and restarted HA and all the add-on's, same result. Inverter 1 working fine, inverter 2, same errors

gcoan commented 7 months ago

Restoring from the 2.4.1 backup taken before I upgraded to 2.4.3 (I jumped straight from .1 to .3) has fixed the issue and I'm now seeing inverter 2 reading OK. Must be a bug in 2.4.3?

image

The logfile is clean as well for inverter 2 (inv 1 battery soc, logged separately as #154 ):

2023-11-29 12:14:31,551 - startup - [CRITICAL] - HA MQTT Service has been found at core-mosquitto
2023-11-29 12:14:31,556 - startup - [INFO] - Supervisor Timezone: Europe/London
2023-11-29 12:14:33,565 - startup - [CRITICAL] - Scanning network for inverters...
2023-11-29 12:14:36,197 - startup - [CRITICAL] - No inverters found...
2023-11-29 12:14:36,199 - startup - [CRITICAL] - Running Redis
2023-11-29 12:14:36,202 - startup - [CRITICAL] - Setting up invertor: 1 of 2
2023/11/29 12:14:36 [notice] 49#49: using the "epoll" event method
2023/11/29 12:14:36 [notice] 49#49: nginx/1.20.2
2023/11/29 12:14:36 [notice] 49#49: OS: Linux 6.1.56
2023/11/29 12:14:36 [notice] 49#49: getrlimit(RLIMIT_NOFILE): 1073741816:1073741816
2023/11/29 12:14:36 [notice] 49#49: start worker processes
2023/11/29 12:14:36 [notice] 49#49: start worker process 53
2023/11/29 12:14:36 [notice] 49#49: start worker process 54
2023/11/29 12:14:36 [notice] 49#49: start worker process 55
2023/11/29 12:14:36 [notice] 49#49: start worker process 56
2023-11-29 12:14:36,247 - startup - [CRITICAL] - Running RQ worker to queue and process givernergy-modbus calls
2023-11-29 12:14:36,247 - startup - [CRITICAL] - Running Invertor read loop every 20s
2023-11-29 12:14:36,251 - startup - [CRITICAL] - Subscribing MQTT Broker for control
2023-11-29 12:14:36,258 - startup - [CRITICAL] - Starting Gunicorn on port 6345
2023-11-29 12:14:36,259 - startup - [CRITICAL] - Setting up invertor: 2 of 2
2023-11-29 12:14:36,373 - startup - [CRITICAL] - Running RQ worker to queue and process givernergy-modbus calls
2023-11-29 12:14:36,374 - startup - [CRITICAL] - Running Invertor read loop every 20s
2023-11-29 12:14:36,414 - startup - [CRITICAL] - Subscribing MQTT Broker for control
2023-11-29 12:14:36,467 - startup - [CRITICAL] - Starting Gunicorn on port 6346
[2023-11-29 12:14:36 +0000] [60] [INFO] Starting gunicorn 21.2.0
[2023-11-29 12:14:36 +0000] [60] [INFO] Listening at: http://0.0.0.0:6345 (60)
[2023-11-29 12:14:36 +0000] [60] [INFO] Using worker: sync
[2023-11-29 12:14:36 +0000] [65] [INFO] Booting worker with pid: 65
[2023-11-29 12:14:36 +0000] [66] [INFO] Booting worker with pid: 66
[2023-11-29 12:14:37 +0000] [72] [INFO] Booting worker with pid: 72
[2023-11-29 12:14:37 +0000] [64] [INFO] Starting gunicorn 21.2.0
[2023-11-29 12:14:37 +0000] [64] [INFO] Listening at: http://0.0.0.0:6346 (64)
[2023-11-29 12:14:37 +0000] [64] [INFO] Using worker: sync
[2023-11-29 12:14:37 +0000] [74] [INFO] Booting worker with pid: 74
[2023-11-29 12:14:37 +0000] [75] [INFO] Booting worker with pid: 75
[2023-11-29 12:14:37 +0000] [76] [INFO] Booting worker with pid: 76
2023-11-29 12:14:37,525 - Inv2 - mqtt_client -  [CRITICAL] - Connecting to MQTT broker for control- core-mosquitto
2023-11-29 12:14:37,586 - Inv1 - mqtt_client -  [CRITICAL] - Connecting to MQTT broker for control- core-mosquitto
2023-11-29 12:14:41,986 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% and no previous value so setting to 1%
2023-11-29 12:14:41,991 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-11-29 12:14:41,995 - Inv1 - read        -  [CRITICAL] - First time running so saving AC Charge status
2023-11-29 12:14:41,999 - Inv1 - read        -  [CRITICAL] - Publishing Home Assistant Discovery messages
2023-11-29 12:14:42,173 - Inv2 - read        -  [CRITICAL] - First time running so saving AC Charge status
2023-11-29 12:14:42,181 - Inv2 - read        -  [CRITICAL] - Publishing Home Assistant Discovery messages
2023-11-29 12:14:49,109 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 12:14:49,110 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-11-29 12:15:02,650 - Inv2 - read        -  [CRITICAL] - Publishing Home Assistant Discovery messages
2023-11-29 12:15:15,215 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 12:15:15,221 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-11-29 12:15:43,207 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 12:15:43,207 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-11-29 12:16:09,264 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 12:16:09,267 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-11-29 12:16:35,213 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 12:16:35,214 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-11-29 12:17:01,364 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 12:17:01,369 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-11-29 12:17:27,376 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2023-11-29 12:17:27,376 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
gcoan commented 6 months ago

@britkat1980 any update on this issue? I had to downgrade to 2.4.1 to get GivTCP working again as whatever the fix was in 2.4.3 didn't work for some circumstances

Thanks

matthewturner commented 6 months ago

I've just had exactly the same problem with my new AIO in the Home Assistant Add-On:

  File "/app/GivTCP_1/mqtt_client.py", line 386, in on_connect
    client.subscribe(MQTT_Topic+"/control/"+GiV_Settings.serial_number+"/#")
AttributeError: type object 'GiV_Settings' has no attribute 'serial_number'

I've tried to troubleshoot by backtracking up the commits as far back as v2.4.0 and running each one in Docker locally. I have been getting the same error each time. Could this be a new issue rather than a regression?

Thanks!

matthewturner commented 6 months ago

Just in case anyone finds themselves here... The solution to my AIO problem was in #141

britkat1980 commented 6 months ago

Does anyone want to test a dev version, which might fix this (or at least point me in the right direction?

gcoan commented 6 months ago

Does anyone want to test a dev version, which might fix this (or at least point me in the right direction?

Yes happy to try a test version but am using GivTCP as a HA add on so how easy is it to run a test version. It's strange that 2.4.3 was working fine for me and then suddenly stopped working. I'm on a gen 1 hybrid and haven't upgraded the firmware for ages so it can't be that

gcoan commented 5 months ago

I may have a potential path to understanding this issue better as it happened again just now ...

Two Gen 1 hybrids, 1 with a battery (inv2), one without (inv1).

Previously had been running stable on GivTCP 2.4.3 but then in November it started reporting the "no serial number" error on one inverter but not the other.

Both inverters on firmware D0.450-A0.451 and GivTCP set to "old firmware=True". Firmware had not been updated for ages.

Only way I managed to clear the issue was to revert back to GivTCP 2.4.1 which worked perfectly.

In December I did try upgrading again to 2.4.3 but it didn't work straight away and I reverted back to 2.4.1

Last week per the suggestion on #165 I was going to try changing the "old firmware" switch to see if that cured the problem. Upgraded to 2.4.3 and GivTCP worked perfectly for over a week until today

Battery had been held at 100% reserve for the start of the agile peak period, and then predbat changed it to Eco mode and dropped the reserve to 4% but I noticed that the inverter wasn't picking up the house load.

On the BBC basic inverter app I could see the battery was on Eco mode, charge set but for before the peak period, discharge set for a future time, reserve 4% but battery wasn't responding to the house load.

Could see in the HA Logbook that updates were being received from inv1 but not inv 2.

Restarted inv2 from the GivEnergy portal, made no difference, no updates appearing in the HA log for that inverter (other inverter working OK), no errors in the GivTCP log, and inverter not picking up house load.

Then saw the "no serial number" error on inverter 2 in the GivTCP log.

Shutdown and restarted GivTCP, logfile showed:

2024-01-18 16:45:12,350 - startup - [CRITICAL] - Setting up invertor: 1 of 2
2024/01/18 16:45:12 [notice] 68#68: using the "epoll" event method
2024/01/18 16:45:12 [notice] 68#68: nginx/1.20.2
2024/01/18 16:45:12 [notice] 68#68: OS: Linux 6.1.71-haos
2024/01/18 16:45:12 [notice] 68#68: getrlimit(RLIMIT_NOFILE): 1073741816:1073741816
2024/01/18 16:45:12 [notice] 68#68: start worker processes
2024/01/18 16:45:12 [notice] 68#68: start worker process 72
2024/01/18 16:45:12 [notice] 68#68: start worker process 73
2024/01/18 16:45:12 [notice] 68#68: start worker process 74
2024/01/18 16:45:12 [notice] 68#68: start worker process 75
2024-01-18 16:45:12,555 - startup - [CRITICAL] - Running RQ worker to queue and process givernergy-modbus calls
2024-01-18 16:45:12,555 - startup - [CRITICAL] - Running Invertor (192.168.1.160) read loop every 20s
2024-01-18 16:45:12,557 - startup - [CRITICAL] - Subscribing MQTT Broker for control
2024-01-18 16:45:12,558 - startup - [CRITICAL] - Starting Gunicorn on port 6345
2024-01-18 16:45:12,586 - startup - [CRITICAL] - Setting up invertor: 2 of 2
2024-01-18 16:45:12,645 - startup - [CRITICAL] - Running RQ worker to queue and process givernergy-modbus calls
2024-01-18 16:45:12,646 - startup - [CRITICAL] - Running Invertor (192.168.1.159) read loop every 20s
2024-01-18 16:45:12,656 - startup - [CRITICAL] - Subscribing MQTT Broker for control
2024-01-18 16:45:12,679 - startup - [CRITICAL] - Starting Gunicorn on port 6346
[2024-01-18 16:45:13 +0000] [79] [INFO] Starting gunicorn 21.2.0
[2024-01-18 16:45:13 +0000] [79] [INFO] Listening at: http://0.0.0.0:6345 (79)
[2024-01-18 16:45:13 +0000] [79] [INFO] Using worker: sync
[2024-01-18 16:45:13 +0000] [84] [INFO] Booting worker with pid: 84
[2024-01-18 16:45:13 +0000] [86] [INFO] Booting worker with pid: 86
[2024-01-18 16:45:13 +0000] [85] [INFO] Booting worker with pid: 85
[2024-01-18 16:45:14 +0000] [83] [INFO] Starting gunicorn 21.2.0
[2024-01-18 16:45:14 +0000] [83] [INFO] Listening at: http://0.0.0.0:6346 (83)
[2024-01-18 16:45:14 +0000] [83] [INFO] Using worker: sync
[2024-01-18 16:45:14 +0000] [87] [INFO] Booting worker with pid: 87
[2024-01-18 16:45:14 +0000] [88] [INFO] Booting worker with pid: 88
[2024-01-18 16:45:14 +0000] [89] [INFO] Booting worker with pid: 89
2024-01-18 16:45:16,891 - Inv1 - mqtt_client -  [CRITICAL] - Connecting to MQTT broker for control- core-mosquitto
2024-01-18 16:45:17,054 - Inv2 - mqtt_client -  [CRITICAL] - Connecting to MQTT broker for control- core-mosquitto
2024-01-18 16:45:21,925 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% and no previous value so setting to 1%
2024-01-18 16:45:21,928 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2024-01-18 16:45:21,936 - Inv1 - read        -  [CRITICAL] - First time running so saving AC Charge status
2024-01-18 16:45:21,942 - Inv1 - read        -  [CRITICAL] - Publishing Home Assistant Discovery messages
2024-01-18 16:45:29,171 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 16:45:29,172 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2024-01-18 16:45:55,364 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 16:45:55,366 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2024-01-18 16:46:47,499 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 16:46:47,501 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2024-01-18 16:46:57,257 - Inv2 - mqtt_client -  [ERROR   ] - No serial_number found in MQTT queue. MQTT Control not available.
Traceback (most recent call last):
  File "/app/GivTCP_2/mqtt_client.py", line 402, in <module>
    client.loop_forever()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 1756, in loop_forever
    rc = self._loop(timeout)
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 1164, in _loop
    rc = self.loop_read()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 1556, in loop_read
    rc = self._packet_read()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 2439, in _packet_read
    rc = self._packet_handle()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 3039, in _packet_handle
    return self._handle_connack()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 3138, in _handle_connack
    on_connect(
  File "/app/GivTCP_2/mqtt_client.py", line 386, in on_connect
    client.subscribe(MQTT_Topic+"/control/"+GiV_Settings.serial_number+"/#")
AttributeError: type object 'GiV_Settings' has no attribute 'serial_number'
2024-01-18 16:47:05,938 - Inv2 - read        -  [ERROR   ] - 10 failed inverter reads in a row so removing regCache to force update

In the GivEnergy portal, did a 'reset to defaults' to clear the 'not picking up house load' issue

Series of timeout errors in the GivTCP log and then it started posting updates for inv2 in the HA history:

2024-01-18 16:56:56,059 - Inv2 - sync        -  [ERROR   ] - Connection to (192.168.1.159, 8899) failed: timed out
2024-01-18 16:56:59,210 - Inv2 - sync        -  [ERROR   ] - Connection to (192.168.1.159, 8899) failed: timed out
2024-01-18 16:57:01,741 - Inv2 - sync        -  [ERROR   ] - Connection to (192.168.1.159, 8899) failed: timed out
2024-01-18 16:57:07,822 - Inv2 - read        -  [ERROR   ] - 10 failed inverter reads in a row so removing regCache to force update...
2024-01-18 16:57:15,590 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 16:57:41,055 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 16:57:57,633 - Inv2 - read        -  [CRITICAL] - First time running so saving AC Charge status
2024-01-18 16:57:57,644 - Inv2 - read        -  [CRITICAL] - Publishing Home Assistant Discovery messages
2024-01-18 16:58:06,880 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 16:58:32,531 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 16:58:57,846 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 16:59:49,499 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 17:00:15,776 - Inv2 - read        -  [CRITICAL] - Publishing Home Assistant Discovery messages
2024-01-18 17:00:24,195 - Inv2 - write       -  [INFO    ] - Setting battery reserve target to: 99
2024-01-18 17:00:26,098 - Inv2 - write       -  [INFO    ] - Setting shallow charge 99 was a success
2024-01-18 17:00:30,942 - Inv2 - write       -  [INFO    ] - Setting battery reserve target to: 99
2024-01-18 17:00:34,049 - Inv2 - write       -  [INFO    ] - Setting shallow charge 99 was a success
2024-01-18 17:00:39,066 - Inv2 - read        -  [CRITICAL] - Publishing Home Assistant Discovery messages
2024-01-18 17:00:39,860 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 17:01:06,096 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 17:01:57,616 - Inv1 - read        -  [ERROR   ] - "Battery SOC" reported as: 0% so using previous value
2024-01-18 17:02:22,596 - Inv2 - read        -  [CRITICAL] - Publishing Home Assistant Discovery messages
2024-01-18 17:02:25,646 - Inv2 - write       -  [INFO    ] - Setting battery reserve target to: 4
2024-01-18 17:02:32,311 - Inv2 - write       -  [INFO    ] - Setting shallow charge 4 was a success
2024-01-18 17:02:37,725 - Inv2 - read        -  [ERROR   ] - Battery Object empty so skipping

So it would appear that at least in this occasion the 'no serial number' error on a gen 1 hybrid (old firmware) on GivTCP 2.4.3 was caused by the inverter getting stuck, not picking up house load, and a reset to defaults of the inverter cured the inverter not discharging and cured GivTCP 'no serial number' error

charlie-chester commented 2 months ago

I'm getting a similar issues with GivTCP not reading the inverter. I'm on 2.4.2. How do you go back to 2.4.1 to test?

gcoan commented 2 months ago

I'm getting a similar issues with GivTCP not reading the inverter. I'm on 2.4.2. How do you go back to 2.4.1 to test?

The only way I know of going back to an earlier version of an add-on is to do a restore of the add-on from a backup you took before the upgrade. Either the pre-upgrade backup that HA takes, or if you have any prior full backup you can do a partial restore and just select the GivTCP add-on.

I found on my gen 1 hybrid that when the 'no serial number' issue last occurred, a reset to defaults in the givenergy portal cured the problem and I didn't have to restore GivTCP

charlie-chester commented 2 months ago

I haven't got a back up going back that far unfortunately.

I've had Predbat on now for a while working perfectly. About a week or so ago as far as I can tell I started getting REST errors in the Status. With help from Trefor I tried a few things but can't get to the bottom of it. Reading your post tonight though I think it's a bug with GivTCP as you identified. I'm getting different errors in the log but I have had the serial number error which is how I found your post.

These are some if the errors I'm getting.

2024-04-08 00:36:25,551 - Inv1 - write - [INFO ] - Setting shallow charge 4 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 0xffff7f834400>)

2024-04-08 00:35:47,396 - Inv1 - write - [INFO ] - Setting dynamic mode 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 0xffff7f82c400>)

I've tried the reset to defaults but I'm still getting them.

Basically I think that Predbat is sending the command to the Inverter correctly as I can see from my battery card it's doing what is required but the confirmation message isn't coming back! It's not every time but probably 50% of them.

charlie-chester commented 2 months ago

My log this morning. 

2024-04-08 07:57:06,749 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 Start to: 07:30
2024-04-08 07:57:09,662 - Inv1 - write       -  [INFO    ] - Setting Charge Slot Start 1 was a success
2024-04-08 07:57:16,750 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 Start to: 07:30
2024-04-08 07:57:19,536 - Inv1 - write       -  [INFO    ] - Setting Charge Slot Start 1 was a success
2024-04-08 07:57:26,754 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 Start to: 07:30
2024-04-08 07:57:31,154 - Inv1 - write       -  [INFO    ] - Setting Charge Slot Start 1 was a success
2024-04-08 07:57:36,758 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 Start to: 07:30
2024-04-08 07:57:39,636 - Inv1 - write       -  [INFO    ] - Setting Charge Slot Start 1 was a success
2024-04-08 07:57:46,763 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 Start to: 07:30
2024-04-08 07:57:53,261 - Inv1 - write       -  [INFO    ] - Setting Charge Slot Start 1 was a success
2024-04-08 07:57:56,803 - Inv1 - write       -  [INFO    ] - Setting Charge Slot End 1 to: 08:00
2024-04-08 07:57:59,649 - Inv1 - write       -  [INFO    ] - Setting Charge Slot End 1 was a success
2024-04-08 07:58:06,793 - Inv1 - write       -  [INFO    ] - Setting Charge Slot End 1 to: 08:00
2024-04-08 07:58:15,136 - Inv1 - write       -  [INFO    ] - Setting Charge Slot End 1 was a success
2024-04-08 08:00:16,376 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 00:00 - 02:40
2024-04-08 08:00:20,642 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:02:21,481 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 08:30
2024-04-08 08:02:29,151 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:02:36,330 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 08:30
2024-04-08 08:02:40,560 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:07:10,465 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 00:00 - 02:40
2024-04-08 08:07:14,747 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:12:07,569 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 11:00
2024-04-08 08:12:14,132 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:17:09,015 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 08:30
2024-04-08 08:17:12,804 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 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 0xffffa7b9d200>)
2024-04-08 08:17:23,396 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 08:30
2024-04-08 08:17:33,790 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:17:40,591 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 08:30
2024-04-08 08:17:44,089 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 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 0xffffa7ba5080>)
2024-04-08 08:17:51,056 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 08:30
2024-04-08 08:17:58,911 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:18:05,849 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 08:30
2024-04-08 08:18:10,281 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:22:05,044 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 13:00
2024-04-08 08:22:09,398 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:25:19,635 - Inv1 - sync        -  [ERROR   ] - Connection to (192.168.50.176, 8899) failed: timed out
2024-04-08 08:27:08,304 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 11:00
2024-04-08 08:27:12,484 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:32:09,323 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 13:00
2024-04-08 08:32:13,621 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:33:09,967 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2024-04-08 08:37:07,623 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 11:00
2024-04-08 08:37:11,919 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:42:04,763 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 13:00
2024-04-08 08:42:09,022 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:42:17,819 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 13:00
2024-04-08 08:42:28,491 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 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 0xffffa7ba09c0>)
2024-04-08 08:42:39,463 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 13:00
2024-04-08 08:42:42,950 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 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 0xffffa7b9d180>)
2024-04-08 08:42:53,639 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 13:00
2024-04-08 08:43:04,263 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 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 0xffffa7ba1240>)
2024-04-08 08:43:13,091 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 13:00
2024-04-08 08:43:17,412 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:47:05,372 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 12:00
2024-04-08 08:47:09,565 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:52:04,593 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 13:00
2024-04-08 08:52:08,833 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 08:57:06,058 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 12:00
2024-04-08 08:57:10,261 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:02:11,129 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 13:00
2024-04-08 09:02:15,478 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:07:05,173 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 11:00
2024-04-08 09:07:09,527 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:07:20,096 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 11:00
2024-04-08 09:07:29,229 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:07:41,550 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 11:00
2024-04-08 09:07:51,039 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:07:59,692 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 11:00
2024-04-08 09:08:04,049 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:08:11,097 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 11:00
2024-04-08 09:08:19,387 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 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 0xffffa7ba0f40>)
2024-04-08 09:09:01,858 - Inv1 - read        -  [ERROR   ] - 10 failed inverter reads in a row so removing regCache to force update...
2024-04-08 09:09:22,883 - Inv1 - read        -  [CRITICAL] - First time running so saving AC Charge status
2024-04-08 09:12:03,793 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 12:30
2024-04-08 09:12:08,348 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:17:04,649 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 12:00
2024-04-08 09:17:08,851 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:22:03,912 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 13:00
2024-04-08 09:22:08,340 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:27:08,507 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 10:00
2024-04-08 09:27:12,905 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:32:07,673 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 12:30
2024-04-08 09:32:11,221 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 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 0xffffa7ba5040>)
2024-04-08 09:32:18,236 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 12:30
2024-04-08 09:32:22,827 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:32:35,208 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 12:30
2024-04-08 09:32:41,548 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 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 0xffffa7ba1180>)
2024-04-08 09:32:52,293 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 12:30
2024-04-08 09:32:56,590 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:33:05,343 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 12:30
2024-04-08 09:33:13,296 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 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 0xffffa7ba5180>)
2024-04-08 09:37:04,245 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 10:30
2024-04-08 09:37:08,528 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
2024-04-08 09:41:35,799 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2024-04-08 09:42:03,196 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 12:00
2024-04-08 09:42:06,679 - Inv1 - sync        -  [ERROR   ] - Connection to (192.168.50.176, 8899) failed: timed out
2024-04-08 09:42:06,681 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 failed: (<class 'AssertionError'>, AssertionError('Unexpected response from remote end: Modbus Error: [Connection] Failed to connect[ModbusTcpClient(192.168.50.176:8899)]'), <traceback object at 0xffffa7bb0b80>)
2024-04-08 09:42:13,765 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 to: 08:00 - 12:00
2024-04-08 09:42:18,171 - Inv1 - write       -  [INFO    ] - Setting Charge Slot 1 was a success
gcoan commented 2 months ago

I agree, it very much looks like comms errors talking to the inverter.

How is your inverter connected to the internet? If its a mesh wifi, is it connected to a node that maybe doesn't have a good signal ?

Try restarting GivTCP and MQTT add-on's, sometimes that improves things.

charlie-chester commented 2 months ago

Trefor said it may be a network issue but I've done everything I can to try and sort that but nothing seems to make a difference.

I have a Virgin Media Router with the wifi off and hard wired to an Asus Mesh set up. My main Router is in the living room and the Inverter is in the Garage. There is a node in the garage with Great connection.

The Home Assistant Green is in my Office / Bedroom hard wired to another Node also with reported Great Connection.

I've moved things a much as I can with no avail. I've also had a node in the garage with 2 ethernet ports one hard wired to Home Assistant and the other to the inverter.

Apart from Hard Wiring direct to my main router I've tried it all. I would need a cable longer than I have at the moment to test.

dmlambert99 commented 1 month ago

I came looking here with a similar issue. I have had GivTCP running for over a year and been on 2.4.3 for several months with no issues (Gen1 AC and 9.5kW battery with old firmware flag enabled) , then suddenly yesterday it stopped working. I did not make the connection to GivTCP at there time but there was a general settings notification about a corrupt cache file which I now think may have been significant in my case.

I was getting same log entries as above - (initial finding invertor but then line with no serial number and continual log entry message about 10 failed reads) but I could connect to the invertor via IP address and app and portals were working. I tried suggestions above and similar threads - restarting addon, HA, rolling back/forward version, resetting invertor to defaults etc. changing oldfirmware flag on/off but nothing seem to work for me. I then came across a comment in a FB group and tried deleting a few .pkl files in the config/GivTCP directly and restarting the addon and that has fixed my issue. Hope this info helps.