Issue after configuration

[rubenltp]

Hi!
I'm trying to configure that component but I get an error (I'll pass it at the end). I also have the sems portal component, but Il prefer this one, to get the data from the inverter directly.
What am i doing bad?

Thanks for you help!

Error:

Logger: homeassistant
Source: custom_components/goodwe/sensor.py:104
First occurred: 9:20:05 (1 occurrences)
Last logged: 9:20:05

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/config/custom_components/goodwe/sensor.py", line 98, in async_refresh
    inverter_response = await self.entity.inverter.read_runtime_data()
  File "/config/custom_components/goodwe/goodwe_inverter.py", line 1000, in read_runtime_data
    raw_data = await self._read_from_socket(self._READ_DEVICE_RUNNING_DATA)
  File "/config/custom_components/goodwe/goodwe_inverter.py", line 407, in _read_from_socket
    return await command.execute(self.host, self.port)
  File "/config/custom_components/goodwe/goodwe_inverter.py", line 374, in execute
    await on_response_received
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/config/custom_components/goodwe/sensor.py", line 104, in async_refresh
    raise PlatformNotReady
homeassistant.exceptions.PlatformNotReady

[mletenay]

Which inverter model ?
And/or can you check the connection (and provide the logs) by executing the inverter_test.py ?

[rubenltp]

My inverter model is: GW5048-EM
I'm ussing dockers. In wich docker I must to execute this inverter_test.py?
I'm trying to execute on host and on homeassistant but it return an error "import custom_components.goodwe.goodwe_inverter as inverter"

[mletenay]

You need to checkout/download whole directory structure (resp. the custom_components/goodwe folder) to be able to run the inverter_test.py.
Anyway, looking at the code, it smells like network issue, either it can't connect to the inverter or there are too many drop-outs.
The inverter_test.py output would help.

[rubenltp]

Ok, I think I got it. Here's the output.

2020-10-05 17:13:24,368 __init__(53) - DEBUG: Using selector: EpollSelector
2020-10-05 17:13:24,368 discover(471) - DEBUG: Probing inverter at 192.168.2.10:8899
2020-10-05 17:13:24,368 connection_made(315) - DEBUG: Send: 'aa55c07f0102000241'
2020-10-05 17:13:24,610 datagram_received(326) - DEBUG: Received: 'aa557fc001824d31303130394757353034382d454d20ffffffffffffffffffffffffffffffff3935303438454d553139335730303433333630303431302d30343030302d3130033431302d30323033342d303910'
2020-10-05 17:13:24,610 datagram_received(334) - DEBUG: Unexpected response length: expected (85, 86), received: 84
2020-10-05 17:13:24,610 connection_made(315) - DEBUG: Send: 'aa55c07f0102000241'
2020-10-05 17:13:25,012 datagram_received(326) - DEBUG: Received: 'aa557fc001824d31303130394757353034382d'
2020-10-05 17:13:25,013 datagram_received(334) - DEBUG: Unexpected response length: expected (85, 86), received: 19
2020-10-05 17:13:25,013 connection_made(315) - DEBUG: Send: 'aa55c07f0102000241'
2020-10-05 17:13:25,437 datagram_received(326) - DEBUG: Received: 'aa557fc001824d31303130394757353034382d454d20ffffffffffffffffffffffffffffffff3935303438454d553139335730303433333630303431302d30343030302d3130033431302d30323033342d3039101f64'
2020-10-05 17:13:25,437 discover(485) - DEBUG: Detected ES inverter GW5048-EM, S/N:95048EMU193W0043
2020-10-05 17:13:25,438 __init__(53) - DEBUG: Using selector: EpollSelector
2020-10-05 17:13:25,438 connection_made(315) - DEBUG: Send: 'aa55c07f0106000245'
2020-10-05 17:13:25,913 datagram_received(326) - DEBUG: Received: 'aa557fc00186850cdf002b020f140005010213000000500104003c007d008c00005f005f64020000010945004c000013890109450003074a1389010201910000000000014869'
2020-10-05 17:13:25,913 datagram_received(334) - DEBUG: Unexpected response length: expected (142, 149), received: 70
2020-10-05 17:13:25,913 connection_made(315) - DEBUG: Send: 'aa55c07f0106000245'
2020-10-05 17:13:26,391 datagram_received(326) - DEBUG: Received: 'aa557fc00186850ce7002b020f1000050102130000005001040040007d008c00005f005f6402000001094a004d000213'
2020-10-05 17:13:26,392 datagram_received(334) - DEBUG: Unexpected response length: expected (142, 149), received: 48
2020-10-05 17:13:26,392 connection_made(315) - DEBUG: Send: 'aa55c07f0106000245'
2020-10-05 17:13:26,867 datagram_received(326) - DEBUG: Received: 'aa557fc00186850cfb002b'
2020-10-05 17:13:26,867 datagram_received(334) - DEBUG: Unexpected response length: expected (142, 149), received: 11
2020-10-05 17:13:26,867 connection_made(315) - DEBUG: Send: 'aa55c07f0106000245'
2020-10-05 17:13:27,373 datagram_received(326) - DEBUG: Received: 'aa557fc00186850cfe002b020f330005010213000000500104003e007d008c00005f005f6402000001094c004d0004138a01094c0003075f138a010201910000000000014869000022370097008d00016611074101003000000200010000fff2000000400000140a05110c1100000000000000000000000000000000000000000000000000007b04000070'
2020-10-05 17:13:27,374 datagram_received(334) - DEBUG: Unexpected response length: expected (142, 149), received: 139
2020-10-05 17:13:27,374 connection_made(315) - DEBUG: Send: 'aa55c07f0106000245'
2020-10-05 17:13:27,439 _timeout_heartbeat(350) - DEBUG: Timeout #5, closing socket
Traceback (most recent call last):
  File "inverter_test.py", line 18, in <module>
    response = asyncio.run(inverter.read_runtime_data())
  File "/usr/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 584, in run_until_complete
    return future.result()
concurrent.futures._base.CancelledError

[mletenay]

Something very odd is happening on your network and it is truncating the response packets.
You should have received response for the "version" request with length of 86 bytes, but in 3 attempts you got (same content) various lengths - 84, 19 and 86.
Same problems for the "info" request - never got the full-size response.
UDP is unreliable, but this is way too much.
Can you check your network ? Do you have sufficient wifi signal strength ?

[rubenltp]

Yes, this inverter is connected by an Ethernet module, not the WiFi one. Before the change of the module we have problems with the connection, but now is all perfect and correct. Could the Ethernet module be the problem? If I tried to use one of the examples to request to 48899 port as the omnik inverter from a python script I have a response without problems, with the name of the Ethernet module; and the app of the inverter works fine too. Tell me what I can do to get more information to solve the problems. Thanks El lun., 5 oct. 2020 17:30, mletenay <notifications@github.com> escribió:

…

Something very odd is happening on your network and it is truncating the response packets. You should have received response for the "version" request with length of 86 bytes, but in 3 attempts you got (same content) various lengths - 84, 19 and 86. Same problems for the "info" request - never got the full-size response. UDP is unreliable, but this is way too much. Can you check your network ? Do you have sufficient wifi signal strength ? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#10 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AJKE7WYJOXFR5S63IPPDAULSJHRCRANCNFSM4SEUWUWQ> .

[mletenay]

I'm not sure what is the source of the problems, if it is IP stack of the HA machine, or some docker network issue or some actual network problem. Under normal circumstances, you should not get incomplete udp packets.
There's very little I can do on the python code level, actually the only thing I can do is to increase the re-try count from 3 to some larger number. And I can improve the exception handling.
But at best case you'll get very unreliable readings from the inverter.

I suggest to use the inverter_test.py to somehow trace the source of the network problems. In normal situations, you should get the packets with right size and only very seldom some re-try attempts.

[rubenltp]

I've tried again the inverter_test.py and I have this output
2020-10-06 08:32:04,359 __init__(53) - DEBUG: Using selector: EpollSelector 2020-10-06 08:32:04,359 discover(471) - DEBUG: Probing inverter at 192.168.2.10:8899 2020-10-06 08:32:04,360 connection_made(315) - DEBUG: Send: 'aa55c07f0102000241' 2020-10-06 08:32:04,534 datagram_received(326) - DEBUG: Received: 'aa557fc001824d31303130394757353034382d454d20ffffffffffffffffffffffffffffffff3935303438454d553139335730303433333630303431302d30343030302d3130033431302d30323033342d3039101f64' 2020-10-06 08:32:04,535 discover(485) - DEBUG: Detected ES inverter GW5048-EM, S/N:95048EMU193W0043 2020-10-06 08:32:04,535 __init__(53) - DEBUG: Using selector: EpollSelector 2020-10-06 08:32:04,536 connection_made(315) - DEBUG: Send: 'aa55c07f0106000245' 2020-10-06 08:32:05,083 datagram_received(326) - DEBUG: Received: 'aa557fc00186850a010001020dcc00010201ff0000005000dc0005007d000000000900096401000001091c0001021d138801091c0003021d1387' 2020-10-06 08:32:05,083 datagram_received(334) - DEBUG: Unexpected response length: expected (142, 149), received: 58 2020-10-06 08:32:05,083 connection_made(315) - DEBUG: Send: 'aa55c07f0106000245' 2020-10-06 08:32:05,560 datagram_received(326) - DEBUG: Received: 'aa557fc0018685' 2020-10-06 08:32:05,560 datagram_received(334) - DEBUG: Unexpected response length: expected (142, 149), received: 7 2020-10-06 08:32:05,560 connection_made(315) - DEBUG: Send: 'aa55c07f0106000245' 2020-10-06 08:32:06,046 datagram_received(326) - DEBUG: Received: 'aa557fc00186850a000001020dd000010201ff0000005000dc0005007d0000000009000964010000010922000102161388010922000302251388010200e700000000000148cc0000' 2020-10-06 08:32:06,046 datagram_received(334) - DEBUG: Unexpected response length: expected (142, 149), received: 72 2020-10-06 08:32:06,046 connection_made(315) - DEBUG: Send: 'aa55c07f0106000245' 2020-10-06 08:32:06,529 datagram_received(326) - DEBUG: Received: 'aa557fc001868506410001020d9b00000201ff0000005000dc0005007d0000000009000964010000010920000102131388010920000302241387010200e700000000000148cc000022460026003b0001668b001301003002000100010000fc7f000800060000140a06081e3700000000000000000000000000000000000000000000000000007b08000070c510ef' vpv1: PV1 Voltage = 160.1 V ipv1: PV1 Current = 0.1 A ppv1: PV1 Power = 16 W pv1_mode: PV1 Mode = 2 pv1_mode_label: PV1 Mode = Working,PV has a power output vpv2: PV2 Voltage = 348.3 V ipv2: PV2 Current = 0.0 A ppv2: PV2 Power = 0 W pv2_mode: PV2 Mode = 2 pv2_mode_label: PV2 Mode = Working,PV has a power output ppv: PV Power = 16 W vbattery1: Battery Voltage = 51.1 V battery_temperature: Battery Temperature = 22.0 C ibattery1: Battery Current = 0.5 A pbattery1: Battery Power = 26 W battery_charge_limit: Battery Charge Limit = 125 A battery_discharge_limit: Battery Discharge Limit = 0 A battery_status: Battery Status = 0 battery_soc: Battery State of Charge = 9 % battery_soh: Battery State of Health = 100 % battery_mode: Battery Mode = 1 battery_mode_label: Battery Mode = Spare battery_warning: Battery Warning = 0 meter_status: Meter status = 1 vgrid: On-grid Voltage = 233.6 V igrid: On-grid Current = 0.1 A pgrid: On-grid Export Power = -531 W fgrid: On-grid Frequency = 50.0 Hz grid_mode: Work Mode = 1 grid_mode_label: Work Mode = The inverter is generating vload: Back-up Voltage = 233.6 V iload: Back-up Current = 0.3 A pload: On-grid Power = 548 W fload: Back-up Frequency = 49.99 Hz load_mode: Load Mode = 1 load_mode_label: Load Mode = Inverter and the load is disconnected work_mode: Energy Mode = 2 work_mode_label: Energy Mode = Normal(On-Grid) temperature: Inverter Temperature = 23.1 C error_codes: Error Codes = 0 e_total: Total PV Generation = 1863.6 kWh h_total: Hours Total = 8774 e_day: Today's PV Generation = 3.8 kWh e_load_day: Today's Load Consumption = 5.9 kWh e_load_total: Total Load = 2625.1 kW total_power: Total Power = 19 W grid_in_out: On-grid Mode = 2 grid_in_out_label: On-grid Mode = Inverter gets power from grid pback_up: Back-up Power = 1 W plant_power: Plant Power = 549 W diagnose_result: Diag Status = 524294 house_consumption: House Comsumption = 573 W

Well, as you can see there is all the data of the inverter. I think, the problem could be the time that the script is waiting the response, or de number of the attemps, as you said before.
Maybe, changing the handling of this in the script, thouth it translate to less accuracy or less reliability; it can fix the error on hassio.

P.S. Sorry about my english, it isn't very good.

[mletenay]

I have improved the exception handling, so you should get data in HA, at least from time to time.
But until the packet truncation problem is resolved, it will be unreliable.

Download the updated sources (mostly goodwe_inverter.py) and try to execute that several times to see how often you get correct results.
Then increase the "timeout: int = 2" value on line 308 in the goodwe_inverter.py and test it again if it has any effect on the packet truncation and data retrieval reliability.

[rubenltp]

Thanks @mletenay, it's seems to work without problems. Finally, I didn't modify the timeout, maybe, It can have lost packets, but in the front I see all the sensors well.
Thanks for your work!