pymodbus-dev / pymodbus

A full modbus protocol written in python
Other
2.25k stars 921 forks source link

ModbusException not trown while under the hood asyncio.TimeoutError("Server not responding") is fired #2228

Closed ArdJonker closed 2 months ago

ArdJonker commented 3 months ago

Versions

Pymodbus Specific

Description

Unfortunately the modbus module in the hardware i use has the tenancy to crash every 1 to 3 weeks. I need to be able to detect this reliably to notify the admin.

I now can only do this by counting retries and a total timeout, i would expect to be able to catch a specific Exception. But the ModbusException does not fire, eventhough asyncio.TimeoutError("Server not responding") is fired. Maybe this is because of TypeError: close() got an unexpected keyword argument 'intern'?

Code

import asyncio
import logging
import pymodbus.client as modbusClient
from pymodbus import ModbusException
from pymodbus import pymodbus_apply_logging_config

pymodbus_apply_logging_config("DEBUG")
_logger = logging.getLogger(__file__)
_logger.setLevel("DEBUG")

console_handler = logging.StreamHandler()
console_handler.setLevel(logging.DEBUG)

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
console_handler.setFormatter(formatter)

_logger.addHandler(console_handler)

def setup_async_client():
    """Run client setup."""
    client = modbusClient.AsyncModbusTcpClient(
        host = "192.168.xxx.xxx",
        port=502,
        timeout=5,
        retries=6,
        reconnect_delay=1,
        reconnect_delay_max=10,
        retry_on_empty=True,
    )
    return client

async def run_async_client(client, modbus_calls=None):
    _logger.info("### Client starting")
    await client.connect()
    assert client.connected
    if modbus_calls:
        await modbus_calls(client)
    client.close()
    _logger.info("### End of Program")

async def run_a_few_calls(client):
    SET_ACTION_REGISTER= 257
    start_charging = 1
    stop_charging = 2

    charger_connected_car_state_of_charge = 538
    charger_charger_state_register = 537
    charger_control_register = 81
    charge_remote_control_value = 1

    try:
        rr = await client.read_holding_registers(charger_charger_state_register, 1, slave=1)
        _logger.info(f"Charger_state: {rr.registers[0]}.")

        rr = await client.write_register(charger_control_register, charge_remote_control_value, slave=1)
        _logger.info(f"Set user control: {rr}.")

        rr = await client.read_holding_registers(charger_connected_car_state_of_charge, 1, slave=1)
        _logger.info(f"Car SoC: {rr.registers[0]}.")

        rr = await client.write_register(SET_ACTION_REGISTER, stop_charging, slave=1)
        _logger.info(f"Stop charging: {rr}.")
    except ModbusException as me:
        _logger.info(f"Exception! {me}")
        pass

async def main():
    testclient = setup_async_client()
    await run_async_client(testclient, modbus_calls=run_a_few_calls)

if __name__ == "__main__":
    asyncio.run(main(), debug=True)

Logging

Test pymodbus with Quasar.py 
2024-07-01 15:04:20,612 - Test pymodbus with Quasar.py - INFO - ### Client starting
2024-07-01 15:04:20,612 DEBUG logging:103 Connecting to 192.168.xxx.xxx:502.
2024-07-01 15:04:20,612 DEBUG logging:103 Connecting comm
2024-07-01 15:04:20,628 DEBUG logging:103 Connected to comm
2024-07-01 15:04:20,629 DEBUG logging:103 Adding transaction 1
2024-07-01 15:04:20,629 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x2 0x19 0x0 0x1
2024-07-01 15:04:20,630 DEBUG logging:103 -> transport: received eof
2024-07-01 15:04:20,631 DEBUG logging:103 Connection lost comm due to None
Exception in callback _SelectorSocketTransport._call_connection_lost(None)
handle: <Handle _SelectorSocketTransport._call_connection_lost(None) created at /.pyenv/versions/3.9.6/lib/python3.9/asyncio/selector_events.py:700>
source_traceback: Object created at (most recent call last):
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
    self.run_forever()
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
    self._run_once()
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/base_events.py", line 1882, in _run_once
    handle._run()
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/selector_events.py", line 813, in _read_ready
    self._read_ready_cb()
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/selector_events.py", line 866, in _read_ready__data_received
    self._read_ready__on_eof()
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/selector_events.py", line 896, in _read_ready__on_eof
    self.close()
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/selector_events.py", line 700, in close
    self._loop.call_soon(self._call_connection_lost, None)
Traceback (most recent call last):
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/selector_events.py", line 978, in _call_connection_lost
    super()._call_connection_lost(exc)
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/selector_events.py", line 736, in _call_connection_lost
    self._protocol.connection_lost(exc)
  File "/.pyenv/versions/3.9.6/lib/python3.9/site-packages/pymodbus/transport/transport.py", line 288, in connection_lost
    self.close(intern=True)
TypeError: close() got an unexpected keyword argument 'intern'
2024-07-01 15:04:25,630 DEBUG logging:103 Adding transaction 1
2024-07-01 15:04:25,631 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x2 0x19 0x0 0x1
2024-07-01 15:04:30,632 DEBUG logging:103 Adding transaction 1
2024-07-01 15:04:30,632 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x2 0x19 0x0 0x1
2024-07-01 15:04:35,633 DEBUG logging:103 Adding transaction 1
2024-07-01 15:04:35,633 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x2 0x19 0x0 0x1
2024-07-01 15:04:40,635 DEBUG logging:103 Adding transaction 1
2024-07-01 15:04:40,635 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x2 0x19 0x0 0x1
2024-07-01 15:04:45,636 DEBUG logging:103 Adding transaction 1
2024-07-01 15:04:45,636 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x2 0x19 0x0 0x1
socket.send() raised exception.
2024-07-01 15:04:50,637 DEBUG logging:103 Adding transaction 1
2024-07-01 15:04:50,638 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x2 0x19 0x0 0x1
socket.send() raised exception.
2024-07-01 15:04:55,638 DEBUG logging:103 Connection lost comm due to Server not responding
Traceback (most recent call last):
  File "/Test pymodbus with Quasar.py", line 83, in <module>
    asyncio.run(main(), debug=True)
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/.pyenv/versions/3.9.6/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/Test pymodbus with Quasar.py", line 79, in main
    await run_async_client(testclient, modbus_calls=run_a_few_calls)
  File "/Test pymodbus with Quasar.py", line 45, in run_async_client
    await modbus_calls(client)
  File "/Test pymodbus with Quasar.py", line 61, in run_a_few_calls
    rr = await client.read_holding_registers(charger_charger_state_register, 1, slave=1)
  File "/.pyenv/versions/3.9.6/lib/python3.9/site-packages/pymodbus/client/base.py", line 179, in async_execute
    self.close(reconnect=True)
  File "/.pyenv/versions/3.9.6/lib/python3.9/site-packages/pymodbus/client/tcp.py", line 92, in close
    super().close(reconnect=reconnect)
  File "/.pyenv/versions/3.9.6/lib/python3.9/site-packages/pymodbus/client/base.py", line 130, in close
    self.connection_lost(asyncio.TimeoutError("Server not responding"))
  File "/.pyenv/versions/3.9.6/lib/python3.9/site-packages/pymodbus/transport/transport.py", line 288, in connection_lost
    self.close(intern=True)
TypeError: close() got an unexpected keyword argument 'intern'

Process finished with exit code 1
janiversen commented 3 months ago

Please try with version 3.6.9, I remember that we have made changes to this problem.

ArdJonker commented 3 months ago

Thanks! I'll give it a try! Problem is, i'll have to wait (an other few weeks maybe..) for the hardware to crash before i can retry.

janiversen commented 2 months ago

Closing as no longer relevant (can be reopened if its still a problem with 3.6.9)