search

britkat1980 / giv_tcp

TCP connection (from inverter) and MQTT implementation
73 stars 34 forks source link

Version 2.3.0 fails to connect to inverter #90

Open Adrian57 opened 1 year ago

Adrian57 commented 1 year ago

Upgraded from Version 2.2.4 to 2.3.0. After upgrade I get many errors like this:

2023-07-30 16:00:30,860 - Inv1 - read - [ERROR ] - Consecutive failure count= 11 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:243), <traceback object at 0x7f804e95c0>)"), <traceback object at 0x7f821f4e80>)

I have restored to 2.2.4 and tried upgrade again. Same problem. Restored again.

(Interestingly, even though in the configuration inverters 2 and 3 are disabled, givtcp goes through a scan on the network for servers. It finds my (only) inverter (a Gen 1 Hybrid) AND my Humax TV box which it interrogates and fails to get inverter info from! I have noticed that even on 2.2.4 it does this as well - though it doesn't cause any problems and hence seems unrelated to this issue)

slip83 commented 1 year ago

Same here... And exactly same story, even after restoring previous version it seems to report "garbage or failed response"

Adrian57 commented 1 year ago

Not quite the same... after restoring mine is fine. Perhaps check it has really restored and also try a reboot?

slip83 commented 1 year ago

Ahh, thanks, I tried again... And indeed it did resolve the issue. I think you're right and I needed a full reboot instead of reload.

Chobnob commented 1 year ago

Confirmed V2.3.0 wont connect with the server as above. Unfortunately as a newbie I don't know how to revert to a previous version.

slip83 commented 1 year ago

Go to settings -> system -> backups and look for givtcp 2.2.4 and then click restore... Fingers crossed you have previously set your system to backup before any update.

Chobnob commented 1 year ago

slip83 Thank you. Doing it now.

russdan commented 1 year ago

Confirmed, restoring from backup to v2.2.24 and restarting resolves the problem for me. Looks like v2.3.0 is broken - I also have a Gen 1 Inverter (GIV-HY3.6) so not sure if that's relevant to the issue?

CaptSB commented 1 year ago

I have Gen 1 Hybrid inverter and haven’t updated anything recently. All data is missing for today in HA. Have generated 9.5kWh but seeing 0 in HA.

Giv_TCP 2.3.0 ; HA 2023.7.3

Something has definitely stopped working.

Cheers!

On Sun, 30 Jul 2023 at 18:01, russdan @.***> wrote:

Confirmed, restoring from backup to v2.2.24 and restarting resolves the problem for me. Looks like v2.3.0 is broken - I also have a Gen 1 Inverter (GIV-HY3.6) so not sure if that's relevant to the issue?

— Reply to this email directly, view it on GitHub https://github.com/britkat1980/giv_tcp/issues/90#issuecomment-1657220376, or unsubscribe https://github.com/notifications/unsubscribe-auth/A64N7OUEULM67TFANR57IWDXS2HOPANCNFSM6AAAAAA25IGEVQ . You are receiving this because you are subscribed to this thread.Message ID: @.***>

-- Sent from Gmail Mobile

Yorkie71 commented 1 year ago

Had this issue also. Restored 2.2.4 and all came back online. Confirmed that Setting the old firmware switch resolves this even though I have a hybrid and not AC. Running 451 inverter firmware here. I notice that 2.3.1 has been released overnight addressing the semantics of the configuration text wording so I'm guessing this can be closed now. Great work!

CaptSB commented 1 year ago

2.3.1 has completely messed up my HA now. All of the entities are unknown. Could this go right back to the issue with all entities appended with _2? I just accepted that issue an updated HA to match this.

Looks like I have some work to do here!!

On Mon, 31 Jul 2023 at 06:59, Yorkie71 @.***> wrote:

Had this issue also. Restored 2.2.4 and all came back online. Confirmed that Setting the old firmware switch resolves this even though I have a hybrid and not AC. Running 451 inverter firmware here. I notice that 2.3.1 has been released overnight addressing the semantics of the configuration text wording so I'm guessing this can be closed now. Great work!

— Reply to this email directly, view it on GitHub https://github.com/britkat1980/giv_tcp/issues/90#issuecomment-1657698062, or unsubscribe https://github.com/notifications/unsubscribe-auth/A64N7OVTGJAIIJFLJTX6IMTXS5CTNANCNFSM6AAAAAA25IGEVQ . You are receiving this because you commented.Message ID: @.***>

-- Sent from Gmail Mobile

Yorkie71 commented 1 year ago

2.3.1 has completely messed up my HA now. All of the entities are unknown. Could this go right back to the issue with all entities appended with _2? I just accepted that issue an updated HA to match this. Looks like I have some work to do here!! On Mon, 31 Jul 2023 at 06:59, Yorkie71 @.> wrote: Had this issue also. Restored 2.2.4 and all came back online. Confirmed that Setting the old firmware switch resolves this even though I have a hybrid and not AC. Running 451 inverter firmware here. I notice that 2.3.1 has been released overnight addressing the semantics of the configuration text wording so I'm guessing this can be closed now. Great work! — Reply to this email directly, view it on GitHub <#90 (comment)>, or unsubscribe https://github.com/notifications/unsubscribe-auth/A64N7OVTGJAIIJFLJTX6IMTXS5CTNANCNFSM6AAAAAA25IGEVQ . You are receiving this because you commented.Message ID: @.> -- Sent from Gmail Mobile

Make sure you enable "Inverter 1 - Is it on old firmware?" in the configuration, that should get you back up and running.

CaptSB commented 1 year ago

I have now corrected the settings but all of the numerical entities are now being reported as non-numeric so can’t be displayed in charts etc.

On Mon, 31 Jul 2023 at 07:41, Yorkie71 @.***> wrote:

2.3.1 has completely messed up my HA now. All of the entities are unknown. Could this go right back to the issue with all entities appended with _2? I just accepted that issue an updated HA to match this. Looks like I have some work to do here!! On Mon, 31 Jul 2023 at 06:59, Yorkie71 @.> wrote: Had this issue also. Restored 2.2.4 and all came back online. Confirmed that Setting the old firmware switch resolves this even though I have a hybrid and not AC. Running 451 inverter firmware here. I notice that 2.3.1 has been released overnight addressing the semantics of the configuration text wording so I'm guessing this can be closed now. Great work! — Reply to this email directly, view it on GitHub <#90 (comment) https://github.com/britkat1980/giv_tcp/issues/90#issuecomment-1657698062>, or unsubscribe https://github.com/notifications/unsubscribe-auth/A64N7OVTGJAIIJFLJTX6IMTXS5CTNANCNFSM6AAAAAA25IGEVQ https://github.com/notifications/unsubscribe-auth/A64N7OVTGJAIIJFLJTX6IMTXS5CTNANCNFSM6AAAAAA25IGEVQ . You are receiving this because you commented.Message ID: @.> -- Sent from Gmail Mobile

Make sure you enable "Inverter 1 - Is it on old firmware?" in the configuration, that should get you back up and running.

— Reply to this email directly, view it on GitHub https://github.com/britkat1980/giv_tcp/issues/90#issuecomment-1657761074, or unsubscribe https://github.com/notifications/unsubscribe-auth/A64N7OVKM3POMFTEWSZE4OTXS5HQBANCNFSM6AAAAAA25IGEVQ . You are receiving this because you commented.Message ID: @.***>

-- Sent from Gmail Mobile

CaptSB commented 1 year ago

If it helps, data stopped coming through at approx 01:30 yesterday morning (30th July).

Prior to that, all was working correctly.

On Mon, 31 Jul 2023 at 08:02, Richard Slack @.***> wrote:

I have now corrected the settings but all of the numerical entities are now being reported as non-numeric so can’t be displayed in charts etc.

On Mon, 31 Jul 2023 at 07:41, Yorkie71 @.***> wrote:

2.3.1 has completely messed up my HA now. All of the entities are unknown. Could this go right back to the issue with all entities appended with _2? I just accepted that issue an updated HA to match this. Looks like I have some work to do here!! On Mon, 31 Jul 2023 at 06:59, Yorkie71 @.> wrote: Had this issue also. Restored 2.2.4 and all came back online. Confirmed that Setting the old firmware switch resolves this even though I have a hybrid and not AC. Running 451 inverter firmware here. I notice that 2.3.1 has been released overnight addressing the semantics of the configuration text wording so I'm guessing this can be closed now. Great work! — Reply to this email directly, view it on GitHub <#90 (comment) https://github.com/britkat1980/giv_tcp/issues/90#issuecomment-1657698062>, or unsubscribe https://github.com/notifications/unsubscribe-auth/A64N7OVTGJAIIJFLJTX6IMTXS5CTNANCNFSM6AAAAAA25IGEVQ https://github.com/notifications/unsubscribe-auth/A64N7OVTGJAIIJFLJTX6IMTXS5CTNANCNFSM6AAAAAA25IGEVQ . You are receiving this because you commented.Message ID: @.> -- Sent from Gmail Mobile

Make sure you enable "Inverter 1 - Is it on old firmware?" in the configuration, that should get you back up and running.

— Reply to this email directly, view it on GitHub https://github.com/britkat1980/giv_tcp/issues/90#issuecomment-1657761074, or unsubscribe https://github.com/notifications/unsubscribe-auth/A64N7OVKM3POMFTEWSZE4OTXS5HQBANCNFSM6AAAAAA25IGEVQ . You are receiving this because you commented.Message ID: @.***>

-- Sent from Gmail Mobile

-- Sent from Gmail Mobile

pay4property commented 1 year ago

I had exactly the same issue after 2.3.0 auto-updated. Installing 2.3.2 also made no difference.

Following the guidance here I turned off the auto-update and restored from the 2.2.4 backup then did a full reboot of HA. Mysteriously when HA came back it still said it's running GivTCP 2.3.2 and the error persisted.

I then tried setting the "old firmware" option on all 3 inverters, restarted GivTCP and hey-presto everything seems to be working again :-)

russdan commented 1 year ago

Now I've gone the other way, after issues with 2.3.0/1/2 I restored back to 2.2.4 which was working until this morning when I restarted my HA instance and got:

2023-08-01 08:11:56,304 - startup - [CRITICAL] - HA MQTT Service has been found at core-mosquitto
2023-08-01 08:11:57,658 - startup - [CRITICAL] - We have found the following invertors: {1: '192.168.0.9'}
2023-08-01 08:11:57,658 - startup - [CRITICAL] - GivTCP isAddon: True
2023-08-01 08:11:57,659 - startup - [CRITICAL] - Config directory already exists
2023-08-01 08:11:57,661 - startup - [CRITICAL] - Running Redis
2023-08-01 08:11:57,662 - startup - [CRITICAL] - Running RQ Dashboard on port 9181
2023-08-01 08:11:57,663 - startup - [CRITICAL] - Setting up invertor: 1 of 1
2023-08-01 08:11:57,845 - startup - [CRITICAL] - Recreating settings.py for invertor 1
2023-08-01 08:11:57,847 - startup - [CRITICAL] - Removing old invertor data cache
2023-08-01 08:11:57,848 - startup - [CRITICAL] - Removing old battery data cache
2023-08-01 08:11:57,849 - startup - [CRITICAL] - Old rate data cache not updated today, so deleting
2023-08-01 08:11:57,850 - startup - [CRITICAL] - Running RQ worker to queue and process givernergy-modbus calls
2023-08-01 08:11:57,850 - startup - [CRITICAL] - Running Invertor read loop every 5s
2023-08-01 08:11:57,890 - startup - [CRITICAL] - Subscribing MQTT Broker for control
2023-08-01 08:11:57,898 - startup - [CRITICAL] - Starting Gunicorn on port 6345
RQ Dashboard version 0.6.0
[2023-08-01 08:12:00 +0100] [35] [INFO] Starting gunicorn 20.1.0
[2023-08-01 08:12:00 +0100] [35] [INFO] Listening at: http://0.0.0.0:6345 (35)
[2023-08-01 08:12:00 +0100] [35] [INFO] Using worker: sync
[2023-08-01 08:12:00 +0100] [38] [INFO] Booting worker with pid: 38
 * Running on 0.0.0.0:9181
 * Serving Flask app 'rq_dashboard.cli'
 * Debug mode: off
[2023-08-01 08:12:00 +0100] [39] [INFO] Booting worker with pid: 39
[2023-08-01 08:12:00 +0100] [40] [INFO] Booting worker with pid: 40
2023-08-01 08:12:03,258 - Inv1 - mqtt_client -  [CRITICAL] - Connecting to MQTT broker for control- core-mosquitto
Traceback (most recent call last):
  File "/app/GivTCP_1/read.py", line 64, in getData
    raise Exception ("Garbage or failed inverter Response: "+ str(plant.result))
Exception: Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:113), <traceback object at 0x7f09ac6c0d80>)
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/app/GivTCP_1/read.py", line 1085, in <module>
    globals()[sys.argv[1]]()
  File "/app/GivTCP_1/read.py", line 705, in self_run2
    runAll("True")
  File "/app/GivTCP_1/read.py", line 667, in runAll
    result=getData(full_refresh)
  File "/app/GivTCP_1/read.py", line 79, in getData
    consecFails(e)
  File "/app/GivTCP_1/read.py", line 643, in consecFails
    oldDataCount= pickle.load(inp)
EOFError: Ran out of input

updated to 2.3.2 and still see the same:

2023-08-01 09:36:28,590 - startup - [CRITICAL] - HA MQTT Service has been found at core-mosquitto
2023-08-01 09:36:28,595 - startup - [INFO] - Supervisor Timezone: Europe/London
2023-08-01 09:36:30,602 - startup - [INFO] - Networks available for scanning are: {0: '192.168.0.1'}
2023-08-01 09:36:30,602 - startup - [CRITICAL] - Scanning network for inverters...
2023-08-01 09:36:30,603 - startup - [INFO] - Scanning network (1):192.168.0.1
2023-08-01 09:36:31,925 - startup - [INFO] - 1 Inverters found on 192.168.0.1 - {1: '192.168.0.9'}
2023-08-01 09:36:32,133 - startup - [CRITICAL] - Inverter SAXXXXXXX which is a Gen 1 - Hybrid has been found at: 192.168.0.9
2023-08-01 09:36:32,135 - startup - [CRITICAL] - GivTCP isAddon: True
2023-08-01 09:36:32,135 - startup - [CRITICAL] - Config directory already exists
2023-08-01 09:36:32,138 - startup - [CRITICAL] - Running Redis
2023-08-01 09:36:32,139 - startup - [CRITICAL] - Setting up invertor: 1 of 1
2023-08-01 09:36:32,178 - startup - [CRITICAL] - Recreating settings.py for invertor 1
2023-08-01 09:36:32,179 - startup - [CRITICAL] - Running RQ worker to queue and process givernergy-modbus calls
2023-08-01 09:36:32,179 - startup - [CRITICAL] - Running Invertor read loop every 5s
2023-08-01 09:36:32,179 - startup - [CRITICAL] - Subscribing MQTT Broker for control
2023-08-01 09:36:32,192 - startup - [CRITICAL] - Starting Gunicorn on port 6345
[2023-08-01 09:36:32 +0100] [35] [INFO] Starting gunicorn 21.2.0
[2023-08-01 09:36:32 +0100] [35] [INFO] Listening at: http://0.0.0.0:6345 (35)
[2023-08-01 09:36:32 +0100] [35] [INFO] Using worker: sync
[2023-08-01 09:36:32 +0100] [36] [INFO] Booting worker with pid: 36
[2023-08-01 09:36:32 +0100] [39] [INFO] Booting worker with pid: 39
[2023-08-01 09:36:32 +0100] [40] [INFO] Booting worker with pid: 40
2023-08-01 09:34:34,592 - Inv1 - mqtt_client -  [CRITICAL] - Connecting to MQTT broker for control- core-mosquitto
Traceback (most recent call last):
  File "/app/GivTCP_1/read.py", line 64, in getData
    raise Exception ("Garbage or failed inverter Response: "+ str(plant.result))
Exception: Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:243), <traceback object at 0x7f376dfef400>)
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/app/GivTCP_1/read.py", line 1159, in <module>
    globals()[sys.argv[1]]()
  File "/app/GivTCP_1/read.py", line 787, in self_run2
    runAll("True")
  File "/app/GivTCP_1/read.py", line 749, in runAll
    result=getData(full_refresh)
  File "/app/GivTCP_1/read.py", line 77, in getData
    consecFails(e)
  File "/app/GivTCP_1/read.py", line 725, in consecFails
    oldDataCount= pickle.load(inp)
EOFError: Ran out of input

Setting Old Firmware makes no difference for me with 2.3.2.

In the end I had to restore the 2.2.4 backup from 2 days ago, stop/start the add-in and now it's working again.

My Node-Red jobs (running on separate Node-Red instance not under HA) which direct call the Giv_TCP REST endpoints are working fine, so what's changed with the add-on to cause such a massive breakage?? Is it related to the MQTT changes introduced in 2.3?? What's the best way to debug now?

mogusbi commented 1 year ago

Any updates on this? I'm also having issues connecting to my Gen 1 inverter with the old firmware option ticked

2023-08-05 23:42:48,819 - Inv1 - sync        -  [ERROR   ] - Connection to (192.168.X.XXX, 8899) failed: timed out
2023-08-05 23:44:56,324 - Inv1 - sync        -  [ERROR   ] - Connection to (192.168.X.XXX, 8899) failed: timed out
2023-08-06 00:00:51,087 - Inv1 - mqtt        -  [ERROR   ] - MQTT error trying to send a <class 'list'> to the MQTT broker for: GivEnergy/SDXXXXXXXX/Energy/Today/Battery_Discharge_Energy_Today_kWh
2023-08-06 00:00:51,088 - Inv1 - mqtt        -  [ERROR   ] - MQTT error trying to send a <class 'list'> to the MQTT broker for: GivEnergy/SDXXXXXXXX/Energy/Today/Battery_Throughput_Today_kWh
2023-08-06 00:00:51,092 - Inv1 - mqtt        -  [ERROR   ] - MQTT error trying to send a <class 'list'> to the MQTT broker for: GivEnergy/SDXXXXXXXX/Energy/Rates/Import_ppkwh_Today
2023-08-06 00:14:00,834 - Inv1 - sync        -  [ERROR   ] - Connection to (192.168.X.XXX, 8899) failed: timed out
2023-08-06 05:46:59,927 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-08-06 07:02:27,389 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-08-06 08:28:01,085 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-08-06 13:09:43,872 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-08-06 13:13:36,305 - Inv1 - sync        -  [ERROR   ] - Connection to (192.168.X.XXX, 8899) failed: timed out
2023-08-06 13:13:39,902 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 4 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:113), <traceback object at 0x7f878f1840>)"), <traceback object at 0x7facca6600>)
2023-08-06 13:14:01,147 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 5 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(IR:110), <traceback object at 0x7f878f1980>)"), <traceback object at 0x7fab6d0380>)
2023-08-06 13:19:47,630 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-08-06 13:20:06,509 - Inv1 - sync        -  [ERROR   ] - Connection to (192.168.X.XXX, 8899) failed: timed out
2023-08-06 14:14:28,079 - Inv1 - sync        -  [ERROR   ] - Connection to (192.168.X.XXX, 8899) failed: timed out

Updating to 2.3.3 seems to have improved things a bit but I am still getting some errors

2023-08-07 00:00:50,268 - Inv1 - mqtt        -  [ERROR   ] - MQTT error trying to send a <class 'list'> to the MQTT broker for: GivEnergy/SDXXXXXXXX/Energy/Rates/Import_ppkwh_Today
2023-08-07 05:10:44,929 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-08-07 05:34:26,482 - Inv1 - write       -  [INFO    ] - Setting dayRate via external trigger
2023-08-07 05:34:44,827 - Inv1 - read        -  [INFO    ] - Saving current energy stats at start of day rate tariff (Dynamic)
2023-08-07 06:36:15,190 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-08-07 08:21:53,847 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-08-07 08:31:57,692 - Inv1 - read        -  [ERROR   ] - Battery Object empty so skipping
2023-08-07 09:25:46,228 - Inv1 - sync        -  [ERROR   ] - Connection to (192.168.x.xxx, 8899) failed: timed out
2023-08-07 10:07:34,447 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 4 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:013), <traceback object at 0x7f99fb9880>)"), <traceback object at 0x7fa1f90d40>)
2023-08-07 10:24:45,733 - Inv1 - sync        -  [ERROR   ] - Connection to (192.168.x.xxx, 8899) failed: timed out
russdan commented 1 year ago

I think I might be almost OK now - I went back and re-pulled my docker image of 2.3.3, then I updated the 2.2.4 HA add-in to 2.3.3 and seems to be broadly OK now (this is both with and without "Old firmware" set - I believe I'm not on an old firmware (Inverter Firmware Version D0.450-A0.451, Battery Firmware Version 3013, Last Update Time 2023-07-30 18:02:24). There are still a key failure errors, look to be the same keys as @mogusbi, which appear every few minutes, but the general data pull from the inverter (power, SOC etc) is now working in HA.... 

2023-08-08T09:02:13.684638961Z [2023-08-08 10:02:13 +0100] [56] [INFO] Starting gunicorn 21.2.0
2023-08-08T09:02:13.685355119Z [2023-08-08 10:02:13 +0100] [56] [INFO] Listening at: http://0.0.0.0:6345 (56)
2023-08-08T09:02:13.685433007Z [2023-08-08 10:02:13 +0100] [56] [INFO] Using worker: sync
2023-08-08T09:02:13.690582766Z [2023-08-08 10:02:13 +0100] [59] [INFO] Booting worker with pid: 59
2023-08-08T09:02:13.717142995Z [2023-08-08 10:02:13 +0100] [60] [INFO] Booting worker with pid: 60
2023-08-08T09:02:13.734193404Z [2023-08-08 10:02:13 +0100] [61] [INFO] Booting worker with pid: 61
2023-08-08T09:02:14.662112624Z 2023-08-08 10:02:14,661 - Inv1 - mqtt_client -  [CRITICAL] - Connecting to MQTT broker for control- 127.0.0.1
2023-08-08T09:02:22.979916269Z 2023-08-08 10:02:22,979 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 4 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:113), <traceback object at 0x7f31cdc2b4c0>)"), <traceback object at 0x7fa93ea1b840>)
2023-08-08T09:02:26.482795572Z 2023-08-08 10:02:26,482 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 5 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:013), <traceback object at 0x7f31cdc288c0>)"), <traceback object at 0x7f9898e9c2c0>)
2023-08-08T09:02:31.311634631Z 2023-08-08 10:02:31,311 - Inv1 - read        -  [CRITICAL] - First time running so saving AC Charge status
2023-08-08T09:02:31.314222503Z 2023-08-08 10:02:31,313 - Inv1 - read        -  [CRITICAL] - Publishing Home Assistant Discovery messages
2023-08-08T09:03:38.173083271Z 2023-08-08 10:03:38,172 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 4 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(IR:110), <traceback object at 0x7f31cdc30980>)"), <traceback object at 0x7fa93ea1b9c0>)
2023-08-08T09:05:51.269642288Z 2023-08-08 10:05:51,269 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 4 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:113), <traceback object at 0x7f31cdc30140>)"), <traceback object at 0x7fa93f3dd900>)
2023-08-08T09:15:58.829991819Z 2023-08-08 10:15:58,829 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 7 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(IR:110), <traceback object at 0x7f31cdc248c0>)"), <traceback object at 0x7fa93fd51180>)
2023-08-08T09:20:21.446750885Z 2023-08-08 10:20:21,446 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 6 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:013), <traceback object at 0x7f31cdc1cb40>)"), <traceback object at 0x7fa93fd51180>)
2023-08-08T09:22:36.093092070Z 2023-08-08 10:22:36,092 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 11 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:013), <traceback object at 0x7f31cdc1c980>)"), <traceback object at 0x7fa93ea62ac0>)
2023-08-08T09:22:36.093305149Z 2023-08-08 10:22:36,093 - Inv1 - read        -  [ERROR   ] - 10 failed inverter reads in a row so removing regCache to force update...
2023-08-08T09:23:09.512169560Z 2023-08-08 10:23:09,511 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 4 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:013), <traceback object at 0x7f31cdc1c7c0>)"), <traceback object at 0x7f9898f4e900>)
2023-08-08T09:23:27.758639464Z 2023-08-08 10:23:27,758 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 5 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:013), <traceback object at 0x7f31cdc1c140>)"), <traceback object at 0x7f9898914500>)
2023-08-08T09:23:34.283769394Z 2023-08-08 10:23:34,283 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 6 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(IR:183), <traceback object at 0x7f31cdc18980>)"), <traceback object at 0x7fa93ea62d80>)
2023-08-08T09:23:44.334981199Z 2023-08-08 10:23:44,334 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 7 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:113), <traceback object at 0x7f31cdc18940>)"), <traceback object at 0x7f9898cddd40>)
2023-08-08T09:23:47.783759991Z 2023-08-08 10:23:47,783 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 8 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:013), <traceback object at 0x7f31cdc18800>)"), <traceback object at 0x7f98989583c0>)
2023-08-08T09:23:52.624889642Z 2023-08-08 10:23:52,624 - Inv1 - read        -  [CRITICAL] - First time running so saving AC Charge status

The regCache clear doesn't seem to make any difference, the key errors persist after that....

russdan commented 1 year ago

I increased logging to debug and see the following...

2023-08-08T09:48:49.353834874Z 2023-08-08 10:48:49,353 - Inv1 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-08-08T09:48:49.354113303Z 2023-08-08 10:48:49,353 - Inv1 - transaction -  [DEBUG   ] - Running transaction 5
2023-08-08T09:48:49.355896382Z 2023-08-08 10:48:49,355 - Inv1 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-08-08T09:48:51.358308620Z 2023-08-08 10:48:51,357 - Inv1 - transaction -  [DEBUG   ] - No response received, Expected 164 bytes Recieved 0 bytes !!!!
2023-08-08T09:48:51.358571174Z 2023-08-08 10:48:51,358 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-08-08T09:48:51.359035200Z 2023-08-08 10:48:51,358 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-08-08T09:48:51.865001703Z 2023-08-08 10:48:51,864 - Inv1 - sync        -  [DEBUG   ] - Connection to Modbus server established. Socket ('172.26.0.2', 48629)
2023-08-08T09:48:51.865218521Z 2023-08-08 10:48:51,864 - Inv1 - transaction -  [DEBUG   ] - Current transaction state - TRANSACTION_COMPLETE
2023-08-08T09:48:51.865477830Z 2023-08-08 10:48:51,865 - Inv1 - transaction -  [DEBUG   ] - Running transaction 6
2023-08-08T09:48:51.866180298Z 2023-08-08 10:48:51,865 - Inv1 - sync        -  [DEBUG   ] - New Transaction state 'SENDING'
2023-08-08T09:48:53.867831572Z 2023-08-08 10:48:53,867 - Inv1 - transaction -  [DEBUG   ] - No response received, Expected 164 bytes Recieved 0 bytes !!!!
2023-08-08T09:48:53.869546765Z 2023-08-08 10:48:53,867 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2023-08-08T09:48:53.869584629Z 2023-08-08 10:48:53,868 - Inv1 - transaction -  [DEBUG   ] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2023-08-08T09:48:54.389226858Z 2023-08-08 10:48:54,388 - Inv1 - queue       -  [DEBUG   ] - Starting BLMOVE operation for rq:queue:GivTCP_1 with timeout of 405
2023-08-08T09:48:54.404085225Z 2023-08-08 10:48:54,403 - Inv1 - read        -  [ERROR   ] - Consecutive failure count= 9 -- (<class 'Exception'>, Exception("Garbage or failed inverter Response: ERROR:-(<class 'KeyError'>, KeyError(HR:113), <traceback object at 0x7f6329d9c540>)"), <traceback object at 0x7f669b42b280>)
2023-08-08T09:48:54.457921846Z 2023-08-08 10:48:54,457 - Inv1 - read        -  [DEBUG   ] - Dealt with Power

The keyErrors always appear immediately after the Starting BLMOVE operation ... also there are frequent No response received, Expected 164 bytes Recieved 0 bytes !!!!

Not sure if this helps with identifying the issue?

russdan commented 1 year ago

OK, so having spent more time trying to debug this from what I can see it's the givenergy_modbus client which throws these keyErrors: https://github.com/dewet22/givenergy-modbus/issues/19

They look therefore like noise....... would it be possible @britkat1980 if they were trapped in the code so they didn't cause the 10 failed inverter reads in a row processing, as it looks unnecessary I think for these "stability-related" errors?