search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.88k stars 3.58k forks source link

[sunspec] Discovery of SolarEdge doesn't work with default settings #9270

Open fwolter opened 3 years ago

fwolter commented 3 years ago

@mrbig @ssalonen The discovery of a SolarEdge inverter doesn't work with the default TCP slave transaction time of 60ms. Setting it to 1000ms works. I read that the inverter does only support one TCP connection at a time. So, I don't know if this is an issue of the binding, of the inverter or if it simply needs to be documented.

Here is the log when the discovery fails:

2020-12-06 23:19:52.363 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Scheduling one-off poll task BasicPollTask@3d52d1[request=ModbusReadRequestBlueprint@11bb13c[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=40000,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502],resultCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$997/0x8bba9228@1b44646,failureCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$998/0x8bbafa28@3b7fde]
2020-12-06 23:19:52.367 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Will now execute one-off poll task BasicPollTask@3d52d1[request=ModbusReadRequestBlueprint@11bb13c[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=40000,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502],resultCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$997/0x8bba9228@1b44646,failureCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$998/0x8bbafa28@3b7fde], waited in thread pool for 4
2020-12-06 23:19:52.402 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Scheduling one-off poll task BasicPollTask@ad5538[request=ModbusReadRequestBlueprint@1254d11[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=40002,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502],resultCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$1001/0x8bbae228@14bcf15,failureCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$1002/0x8bbada28@494d18]
2020-12-06 23:19:52.406 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Will now execute one-off poll task BasicPollTask@ad5538[request=ModbusReadRequestBlueprint@1254d11[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=40002,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502],resultCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$1001/0x8bbae228@14bcf15,failureCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$1002/0x8bbada28@494d18], waited in thread pool for 4
2020-12-06 23:19:52.412 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 41 ms, connection: 7, transaction=27, callback=4} [operation ID fbf1be5f-113d-45c8-afa4-2b080425448f]
2020-12-06 23:19:52.436 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: Connection refused (Connection refused). Connection TCPMasterConnection@1744723[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502]
2020-12-06 23:19:52.439 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 1, throwing last error: Connection refused (Connection refused). Connection TCPMasterConnection@1744723[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502]
2020-12-06 23:19:52.441 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection@1744723[socket=Socket[unconnected]] for endpoint ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502]: Connection refused (Connection refused)
2020-12-06 23:19:52.445 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502] -- aborting request ModbusReadRequestBlueprint@1254d11[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=40002,length=2,maxTries=3] [operation ID 7ccf6784-384f-40b1-aad6-db65079a0257]
2020-12-06 23:19:52.447 [WARN ] [al.discovery.SunspecDiscoveryProcess] - Error with read at address 40002: org.openhab.io.transport.modbus.exception.ModbusConnectionException Error connecting to endpoint ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502]
2020-12-06 23:19:52.451 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Scheduling one-off poll task BasicPollTask@1c7522e[request=ModbusReadRequestBlueprint@247712[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50000,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502],resultCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$997/0x8bba9228@fa5815,failureCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$998/0x8bbafa28@c5dd92]
2020-12-06 23:19:52.454 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 44 ms, connection: 35, transaction=0, callback=7} [operation ID 7ccf6784-384f-40b1-aad6-db65079a0257]
2020-12-06 23:19:52.454 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Will now execute one-off poll task BasicPollTask@1c7522e[request=ModbusReadRequestBlueprint@247712[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50000,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502],resultCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$997/0x8bba9228@fa5815,failureCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$998/0x8bbafa28@c5dd92], waited in thread pool for 4
2020-12-06 23:19:52.481 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint@247712[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50000,length=2,maxTries=3]). Will try again soon. Error was: net.wimpi.modbus.ModbusSlaveException Error Code = 2 [operation ID 69b04158-ffac-4b79-aeb4-1da65926d7f5]
2020-12-06 23:19:52.561 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 2 out of 3 failed when executing request (ModbusReadRequestBlueprint@247712[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50000,length=2,maxTries=3]). Will try again soon. Error was: net.wimpi.modbus.ModbusSlaveException Error Code = 2 [operation ID 69b04158-ffac-4b79-aeb4-1da65926d7f5]
2020-12-06 23:19:52.641 [ERROR] [rt.modbus.internal.ModbusManagerImpl] - Last try 3 failed when executing request (ModbusReadRequestBlueprint@247712[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50000,length=2,maxTries=3]). Aborting. Error was: net.wimpi.modbus.ModbusSlaveException Error Code = 2 [operation ID 69b04158-ffac-4b79-aeb4-1da65926d7f5]
2020-12-06 23:19:52.643 [WARN ] [al.discovery.SunspecDiscoveryProcess] - Error with read at address 50000: org.openhab.io.transport.modbus.internal.ModbusSlaveErrorResponseExceptionImpl Slave responsed with error=2
2020-12-06 23:19:52.644 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Scheduling one-off poll task BasicPollTask@1a5c69e[request=ModbusReadRequestBlueprint@185a7f9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502],resultCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$997/0x8bba9228@a1bd67,failureCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$998/0x8bbafa28@1d125c4]
2020-12-06 23:19:52.646 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Will now execute one-off poll task BasicPollTask@1a5c69e[request=ModbusReadRequestBlueprint@185a7f9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502],resultCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$997/0x8bba9228@a1bd67,failureCallback=org.openhab.binding.modbus.sunspec.internal.discovery.SunspecDiscoveryProcess$$Lambda$998/0x8bbafa28@1d125c4], waited in thread pool for 1
2020-12-06 23:19:52.655 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 198 ms, connection: 18, transaction=49, callback=4} [operation ID 69b04158-ffac-4b79-aeb4-1da65926d7f5]
2020-12-06 23:19:52.656 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: Connection refused (Connection refused). Connection TCPMasterConnection@110ffcc[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502]
2020-12-06 23:19:52.657 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 1, throwing last error: Connection refused (Connection refused). Connection TCPMasterConnection@110ffcc[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502]
2020-12-06 23:19:52.658 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection@110ffcc[socket=Socket[unconnected]] for endpoint ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502]: Connection refused (Connection refused)
2020-12-06 23:19:52.659 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502] -- aborting request ModbusReadRequestBlueprint@185a7f9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=2,maxTries=3] [operation ID a57d1c32-4883-4870-ae53-9e5acd1af763]
2020-12-06 23:19:52.661 [WARN ] [al.discovery.SunspecDiscoveryProcess] - Error with read at address 0: org.openhab.io.transport.modbus.exception.ModbusConnectionException Error connecting to endpoint ModbusTCPSlaveEndpoint@30472f[address=192.168.8.2,port=1502]
2020-12-06 23:19:52.662 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 15 ms, connection: 12, transaction=0, callback=2} [operation ID a57d1c32-4883-4870-ae53-9e5acd1af763]
ssalonen commented 3 years ago

I read that the inverter does only support one TCP connection at a time.

I can confirm that the binding uses at most one connection to interface with the slave.

Having said this, it is possible that user has some other tool establishing second connection.

mrbig commented 3 years ago

Hi @fwolter,

I can confirm, that solaredge devices I know are pretty slow devices, so it is normal to increase timeouts and polling interval.

However the parameter you mentioned is a Modbus binding default, wich is shared among lot of other devices not just sunspec things. So adding a higher default value could break (or slow down) many others.

So I guess the best would be to add this information to the documentation.

fwolter commented 3 years ago

I will file a documentation PR. The parameter is not binding wide, but Bridge specific. As you would use the TCP slave bridge only for the connection to one SolarEdge inverter, I think setting the parameter has low side effects.

lsiepel commented 3 months ago

Not sure if the documentation was ever changed, would be nice to either follow up on this or close it. Possible related PR's: https://github.com/openhab/openhab-addons/pulls?q=is%3Apr+sunspec+is%3Aclosed+