Closed 02JanDal closed 1 year ago
looks like you found a problem, I will write a test case to verify it.
The client do reconnect automatically but the app is notified because it might need some handling of the failed call.
Checked an extra time, reconnect automatically do work, however if you do not use the (relatively) new callback, you do not know the state of the connection.
We are in general in the process of refactoring the whole client, because there are a number of "strange" cases, like the reconnect.
Versions
Pymodbus Specific
Server: tcp/rtu/ascii - sync/asyncDescription
Depending on firmware versions and connection type involved, the set of supported registers varies. Therefore, I'm trying to write some code to detect which registers can be used. The most obvious, calling
read_input_registers
on each register and catchingModbusException
s fails by subsequent registers after the failing also failing, even if they should succeed because the failure causes pymodbus to disconnect. Furthermore, callingawait client.close()
seems to keep some internal state which makes further calls not work, only recreating the client object from scratch works.As such, I have a working workaround, however it feels a little hacky. Though I don't understand the Modbus protocol sufficiently to say so with confidence, but I suspect that the root cause might be the server in question misbehaving, however, it would be nice if pymodbus could handle this gracefully (either by automatically reconnecting or at least working after a manual re-connect).
Code and Logs
First attempt:
Log
``` 2023-03-31 05:12:48,976 DEBUG logging:102 Connecting to 192.168.3.20:502. 2023-03-31 05:12:48,976 DEBUG logging:102 Connecting. 2023-03-31 05:12:48,989 DEBUG logging:102 Client connected to modbus server 2023-03-31 05:12:48,989 INFO logging:96 Protocol made connection. 2023-03-31 05:12:48,989 INFO logging:96 Connected to 192.168.3.20:502. Getting 4949 2023-03-31 05:12:48,989 DEBUG logging:102 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x13 0x55 0x0 0x2 2023-03-31 05:12:48,989 DEBUG logging:102 Adding transaction 1 2023-03-31 05:12:48,999 DEBUG logging:102 recv: 0x0 0x1 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x31 0x30 0x41 0x41 2023-03-31 05:12:49,000 DEBUG logging:102 Processing: 0x0 0x1 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x31 0x30 0x41 0x41 2023-03-31 05:12:49,000 DEBUG logging:102 Factory Response[ReadInputRegistersResponse': 4] 2023-03-31 05:12:49,000 DEBUG logging:102 Getting transaction 1 [12592, 16705] Getting 4951 2023-03-31 05:12:49,000 DEBUG logging:102 send: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x4 0x13 0x57 0x0 0x2 2023-03-31 05:12:49,000 DEBUG logging:102 Adding transaction 2 2023-03-31 05:12:49,007 DEBUG logging:102 recv: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x4 0x0 0x1 0x0 2023-03-31 05:12:49,007 DEBUG logging:102 Processing: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x4 0x0 0x1 0x0 2023-03-31 05:12:49,007 DEBUG logging:102 Factory Response[ReadInputRegistersResponse': 4] 2023-03-31 05:12:49,007 DEBUG logging:102 Getting transaction 2 [1024, 256] Getting 4953 2023-03-31 05:12:49,008 DEBUG logging:102 send: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x4 0x13 0x59 0x0 0xf 2023-03-31 05:12:49,008 DEBUG logging:102 Adding transaction 3 2023-03-31 05:12:49,018 DEBUG logging:102 recv: 0x0 0x3 0x0 0x0 0x0 0x2 0x1 0x84 0x2 2023-03-31 05:12:49,018 DEBUG logging:102 Processing: 0x0 0x3 0x0 0x0 0x0 0x2 0x1 0x84 0x2 2023-03-31 05:12:49,018 DEBUG logging:102 Factory Response[132] 2023-03-31 05:12:49,019 ERROR logging:114 General exception: index out of range Fatal error: protocol.data_received() call failed. protocol:Second attempt (manually closing and reconnecting with same client):
Log
``` 2023-03-31 05:16:40,260 DEBUG logging:102 Connecting to 192.168.3.20:502. 2023-03-31 05:16:40,260 DEBUG logging:102 Connecting. 2023-03-31 05:16:40,268 DEBUG logging:102 Client connected to modbus server 2023-03-31 05:16:40,269 INFO logging:96 Protocol made connection. 2023-03-31 05:16:40,269 INFO logging:96 Connected to 192.168.3.20:502. Getting 4949 2023-03-31 05:16:40,269 DEBUG logging:102 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x13 0x55 0x0 0x2 2023-03-31 05:16:40,269 DEBUG logging:102 Adding transaction 1 2023-03-31 05:16:40,278 DEBUG logging:102 recv: 0x0 0x1 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x31 0x30 0x41 0x41 2023-03-31 05:16:40,279 DEBUG logging:102 Processing: 0x0 0x1 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x31 0x30 0x41 0x41 2023-03-31 05:16:40,279 DEBUG logging:102 Factory Response[ReadInputRegistersResponse': 4] 2023-03-31 05:16:40,279 DEBUG logging:102 Getting transaction 1 [12592, 16705] Getting 4951 2023-03-31 05:16:40,279 DEBUG logging:102 send: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x4 0x13 0x57 0x0 0x2 2023-03-31 05:16:40,279 DEBUG logging:102 Adding transaction 2 2023-03-31 05:16:40,287 DEBUG logging:102 recv: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x4 0x0 0x1 0x0 2023-03-31 05:16:40,287 DEBUG logging:102 Processing: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x4 0x0 0x1 0x0 2023-03-31 05:16:40,288 DEBUG logging:102 Factory Response[ReadInputRegistersResponse': 4] 2023-03-31 05:16:40,288 DEBUG logging:102 Getting transaction 2 [1024, 256] Getting 4953 2023-03-31 05:16:40,288 DEBUG logging:102 send: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x4 0x13 0x59 0x0 0xf 2023-03-31 05:16:40,288 DEBUG logging:102 Adding transaction 3 2023-03-31 05:16:40,294 DEBUG logging:102 recv: 0x0 0x3 0x0 0x0 0x0 0x2 0x1 0x84 0x2 2023-03-31 05:16:40,295 DEBUG logging:102 Processing: 0x0 0x3 0x0 0x0 0x0 0x2 0x1 0x84 0x2 2023-03-31 05:16:40,295 DEBUG logging:102 Factory Response[132] 2023-03-31 05:16:40,295 ERROR logging:114 General exception: index out of range Fatal error: protocol.data_received() call failed. protocol:Third attempt (re-creating the client object):
Log
``` 2023-03-31 05:18:10,008 DEBUG logging:102 Connecting to 192.168.3.20:502. 2023-03-31 05:18:10,009 DEBUG logging:102 Connecting. 2023-03-31 05:18:10,015 DEBUG logging:102 Client connected to modbus server 2023-03-31 05:18:10,015 INFO logging:96 Protocol made connection. 2023-03-31 05:18:10,015 INFO logging:96 Connected to 192.168.3.20:502. Getting 4949 2023-03-31 05:18:10,016 DEBUG logging:102 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x13 0x55 0x0 0x2 2023-03-31 05:18:10,016 DEBUG logging:102 Adding transaction 1 2023-03-31 05:18:10,024 DEBUG logging:102 recv: 0x0 0x1 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x31 0x30 0x41 0x41 2023-03-31 05:18:10,024 DEBUG logging:102 Processing: 0x0 0x1 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x31 0x30 0x41 0x41 2023-03-31 05:18:10,024 DEBUG logging:102 Factory Response[ReadInputRegistersResponse': 4] 2023-03-31 05:18:10,024 DEBUG logging:102 Getting transaction 1 [12592, 16705] Getting 4951 2023-03-31 05:18:10,024 DEBUG logging:102 send: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x4 0x13 0x57 0x0 0x2 2023-03-31 05:18:10,024 DEBUG logging:102 Adding transaction 2 2023-03-31 05:18:10,031 DEBUG logging:102 recv: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x4 0x0 0x1 0x0 2023-03-31 05:18:10,031 DEBUG logging:102 Processing: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x4 0x4 0x4 0x0 0x1 0x0 2023-03-31 05:18:10,031 DEBUG logging:102 Factory Response[ReadInputRegistersResponse': 4] 2023-03-31 05:18:10,031 DEBUG logging:102 Getting transaction 2 [1024, 256] Getting 4953 2023-03-31 05:18:10,031 DEBUG logging:102 send: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x4 0x13 0x59 0x0 0xf 2023-03-31 05:18:10,031 DEBUG logging:102 Adding transaction 3 2023-03-31 05:18:10,038 DEBUG logging:102 recv: 0x0 0x3 0x0 0x0 0x0 0x2 0x1 0x84 0x2 2023-03-31 05:18:10,038 DEBUG logging:102 Processing: 0x0 0x3 0x0 0x0 0x0 0x2 0x1 0x84 0x2 2023-03-31 05:18:10,038 DEBUG logging:102 Factory Response[132] 2023-03-31 05:18:10,038 ERROR logging:114 General exception: index out of range Fatal error: protocol.data_received() call failed. protocol: