Noisy warning and possible non-persistent connection issue

[oliver-rew]

Versions

• Python: 3.12.7
• OS: Mac OS 14.6.1 and Linux 6.8.0-49-generic # 49-Ubuntu SMP PREEMPT_DYNAMIC Mon Nov 4 02:06:24 UTC 2024 x86_64 GNU/Linux
• Pymodbus: 3.8.0
• Modbus Hardware (if used): Brainboxes ED-008

Pymodbus Specific

• Client: tcp - sync

Description

I just upgraded to 3.8.0 (thanks!) from 3.7.4 and I noticed a bunch of Not connected, trying to connect! warnings in my logs. It happens more than just the first time.

pymodbus/pymodbus/transaction/transaction.py

Line 100 in b0339e8

Log.warning("Not connected, trying to connect!")

Code and Logs

test program to reproduce.

import pymodbus
from pymodbus.client import ModbusTcpClient

pymodbus.pymodbus_apply_logging_config("DEBUG")

client = ModbusTcpClient(host="192.168.127.201", port=502)

for i in range(3):
    result = client.read_holding_registers(address=0x0000, count=8, slave=255)

    if result.isError():
        raise Exception(f"Error: {result}")

    print("registers: ", result.registers)

Logs:

(.venv) $ pip3 install -q pymodbus==3.8.0
(.venv) $ python3 modbustest.py
2024-12-07 20:46:04,903 DEBUG tcp:197 Connection to Modbus server established. Socket ('192.168.127.3', 61830)
2024-12-07 20:46:04,903 WARNING transaction:100 Not connected, trying to connect!
2024-12-07 20:46:04,903 DEBUG base:201 New Transaction state "SENDING"
2024-12-07 20:46:04,903 DEBUG base:91 Processing: 0x0 0x1 0x0 0x0 0x0 0x13 0xff 0x3 0x10 0x4 0xb7 0x2 0x9c 0x2 0x74 0x2 0x9 0x2 0x62 0x1 0xf7 0x1 0xf9 0x2 0xc
2024-12-07 20:46:04,903 DEBUG decoders:113 decoded PDU function_code(3 sub -1) -> ReadHoldingRegistersResponse(dev_id=0, transaction_id=0, address=0, count=0, bits=[], registers=[1207, 668, 628, 521, 610, 503, 505, 524], status=1)
2024-12-07 20:46:04,903 DEBUG base:101 Frame advanced, resetting header!!
registers:  [1207, 668, 628, 521, 610, 503, 505, 524]
2024-12-07 20:46:04,903 WARNING transaction:100 Not connected, trying to connect!
2024-12-07 20:46:04,904 DEBUG base:201 New Transaction state "SENDING"
2024-12-07 20:46:04,904 DEBUG base:91 Processing: 0x0 0x2 0x0 0x0 0x0 0x13 0xff 0x3 0x10 0x4 0xb7 0x2 0x9c 0x2 0x74 0x2 0x9 0x2 0x62 0x1 0xf7 0x1 0xf9 0x2 0xc
2024-12-07 20:46:04,904 DEBUG decoders:113 decoded PDU function_code(3 sub -1) -> ReadHoldingRegistersResponse(dev_id=0, transaction_id=0, address=0, count=0, bits=[], registers=[1207, 668, 628, 521, 610, 503, 505, 524], status=1)
2024-12-07 20:46:04,904 DEBUG base:101 Frame advanced, resetting header!!
registers:  [1207, 668, 628, 521, 610, 503, 505, 524]
2024-12-07 20:46:04,904 WARNING transaction:100 Not connected, trying to connect!
2024-12-07 20:46:04,904 DEBUG base:201 New Transaction state "SENDING"
2024-12-07 20:46:04,905 DEBUG base:91 Processing: 0x0 0x3 0x0 0x0 0x0 0x13 0xff 0x3 0x10 0x4 0xb7 0x2 0x9c 0x2 0x74 0x2 0x9 0x2 0x62 0x1 0xf7 0x1 0xf9 0x2 0xc
2024-12-07 20:46:04,905 DEBUG decoders:113 decoded PDU function_code(3 sub -1) -> ReadHoldingRegistersResponse(dev_id=0, transaction_id=0, address=0, count=0, bits=[], registers=[1207, 668, 628, 521, 610, 503, 505, 524], status=1)
2024-12-07 20:46:04,905 DEBUG base:101 Frame advanced, resetting header!!
registers:  [1207, 668, 628, 521, 610, 503, 505, 524]

For reference, these are the logs when I run it with 3.7.4

(.venv) $ python3 modbustest.py
2024-12-07 20:46:57,544 DEBUG tcp:169 Connection to Modbus server established. Socket ('192.168.127.3', 61840)
2024-12-07 20:46:57,544 DEBUG transaction:184 Current transaction state - IDLE
2024-12-07 20:46:57,544 DEBUG transaction:193 Running transaction 1
2024-12-07 20:46:57,544 DEBUG transaction:293 SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0xff 0x3 0x0 0x0 0x0 0x8
2024-12-07 20:46:57,544 DEBUG base:250 New Transaction state "SENDING"
2024-12-07 20:46:57,544 DEBUG transaction:317 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-12-07 20:46:57,544 DEBUG transaction:419 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-12-07 20:46:57,544 DEBUG transaction:324 RECV: 0x0 0x1 0x0 0x0 0x0 0x13 0xff 0x3 0x10 0x4 0xb7 0x2 0x9c 0x2 0x74 0x2 0x9 0x2 0x62 0x1 0xf7 0x1 0xf9 0x2 0xc
2024-12-07 20:46:57,544 DEBUG base:92 Processing: 0x0 0x1 0x0 0x0 0x0 0x13 0xff 0x3 0x10 0x4 0xb7 0x2 0x9c 0x2 0x74 0x2 0x9 0x2 0x62 0x1 0xf7 0x1 0xf9 0x2 0xc
2024-12-07 20:46:57,544 DEBUG decoders:103 decode PDU for 3
2024-12-07 20:46:57,544 DEBUG base:102 Frame advanced, resetting header!!
2024-12-07 20:46:57,545 DEBUG transaction:67 Adding transaction 1
2024-12-07 20:46:57,545 DEBUG transaction:78 Getting transaction 1
2024-12-07 20:46:57,545 DEBUG transaction:258 Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
registers:  [1207, 668, 628, 521, 610, 503, 505, 524]
2024-12-07 20:46:57,545 DEBUG transaction:184 Current transaction state - TRANSACTION_COMPLETE
2024-12-07 20:46:57,545 DEBUG transaction:193 Running transaction 2
2024-12-07 20:46:57,545 DEBUG transaction:293 SEND: 0x0 0x2 0x0 0x0 0x0 0x6 0xff 0x3 0x0 0x0 0x0 0x8
2024-12-07 20:46:57,545 DEBUG base:250 New Transaction state "SENDING"
2024-12-07 20:46:57,545 DEBUG transaction:317 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-12-07 20:46:57,545 DEBUG transaction:419 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-12-07 20:46:57,545 DEBUG transaction:324 RECV: 0x0 0x2 0x0 0x0 0x0 0x13 0xff 0x3 0x10 0x4 0xb7 0x2 0x9c 0x2 0x74 0x2 0x9 0x2 0x62 0x1 0xf7 0x1 0xf9 0x2 0xc
2024-12-07 20:46:57,545 DEBUG base:92 Processing: 0x0 0x2 0x0 0x0 0x0 0x13 0xff 0x3 0x10 0x4 0xb7 0x2 0x9c 0x2 0x74 0x2 0x9 0x2 0x62 0x1 0xf7 0x1 0xf9 0x2 0xc
2024-12-07 20:46:57,545 DEBUG decoders:103 decode PDU for 3
2024-12-07 20:46:57,545 DEBUG base:102 Frame advanced, resetting header!!
2024-12-07 20:46:57,545 DEBUG transaction:67 Adding transaction 2
2024-12-07 20:46:57,545 DEBUG transaction:78 Getting transaction 2
2024-12-07 20:46:57,545 DEBUG transaction:258 Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
registers:  [1207, 668, 628, 521, 610, 503, 505, 524]
2024-12-07 20:46:57,545 DEBUG transaction:184 Current transaction state - TRANSACTION_COMPLETE
2024-12-07 20:46:57,545 DEBUG transaction:193 Running transaction 3
2024-12-07 20:46:57,546 DEBUG transaction:293 SEND: 0x0 0x3 0x0 0x0 0x0 0x6 0xff 0x3 0x0 0x0 0x0 0x8
2024-12-07 20:46:57,546 DEBUG base:250 New Transaction state "SENDING"
2024-12-07 20:46:57,546 DEBUG transaction:317 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-12-07 20:46:57,546 DEBUG transaction:419 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-12-07 20:46:57,546 DEBUG transaction:324 RECV: 0x0 0x3 0x0 0x0 0x0 0x13 0xff 0x3 0x10 0x4 0xb7 0x2 0x9c 0x2 0x74 0x2 0x9 0x2 0x62 0x1 0xf7 0x1 0xf9 0x2 0xc
2024-12-07 20:46:57,546 DEBUG base:92 Processing: 0x0 0x3 0x0 0x0 0x0 0x13 0xff 0x3 0x10 0x4 0xb7 0x2 0x9c 0x2 0x74 0x2 0x9 0x2 0x62 0x1 0xf7 0x1 0xf9 0x2 0xc
2024-12-07 20:46:57,546 DEBUG decoders:103 decode PDU for 3
2024-12-07 20:46:57,546 DEBUG base:102 Frame advanced, resetting header!!
2024-12-07 20:46:57,546 DEBUG transaction:67 Adding transaction 3
2024-12-07 20:46:57,546 DEBUG transaction:78 Getting transaction 3
2024-12-07 20:46:57,546 DEBUG transaction:258 Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
registers:  [1207, 668, 628, 521, 610, 503, 505, 524]

Anyway, thanks for the new release and all the hard work, happy to test more if necessary.

[janiversen]

Looks like a bug (but not a serious one), I will investigate.

Thanks for the report.

[topchul]

Thank you for addressing this issue and providing a fix!
I applied the changes locally, and it resolved the 'Not connected, trying to connect!' warning perfectly.
Your quick response and effort are greatly appreciated!

@oliver-rew @janiversen.

[bobemoe]

I just updated from 3.7 to 3.8 and am seeing same Not connected, trying to connect! warning. I'm using RTU though. What version is this fix in how can I see if it resolves my issue too?

[janiversen]

Solved on dev, will be part of v3.8.1