Single byte error response handling

AlexanderLanin commented 7 months ago

Versions

Python: 3.11
OS: Ubuntu 22.04
Pymodbus: 3.6.2
Modbus Hardware (if used): Sungrow Inverter

Pymodbus Specific

Client: tcp async

Description

Current State

When I query my sungrow inverter with a register I'm not supposed to be querying, I'm gettting a malformed package and the connection is dopped.

Wireshark:

TCP Payload: 00 02 00 00 00 02 01 84 02

Request

This line of code assumes that data has more than a single element. However, data in my case is only b'\x84'. The response is being assigned correctly: Exception Response(132, 4, IllegalFunction) But in the marked line I'm getting an pymodbus.logging:General exception: index out of range

See https://github.com/pymodbus-dev/pymodbus/blob/6913e9c829009f3704f75d7cb7fff019c27c6770/pymodbus/factory.py#L351

I can fix this locally by changing

        response.decode(data[1:])

to

        if len(data) > 1:
            response.decode(data[1:])

but I really have no idea what I'm doing here.

However that change allows me to handle the error super nicely on the response object:

        if rr.isError():
            if isinstance(rr, pymodbus.pdu.ExceptionResponse):
                if rr.exception_code == pymodbus.pdu.ModbusExceptions.IllegalFunction:
                    print("unsupported register")

Code and Logs

--------------------
2024-01-09 17:10:45,355 DEBUG logging:103 send: 0x0 0xd 0x0 0x0 0x0 0x6 0x1 0x4 0x13 0x90 0x0 0x2
2024-01-09 17:10:45,355 DEBUG logging:103 Adding transaction 13
2024-01-09 17:10:45,366 DEBUG logging:103 recv: 0x0 0xd 0x0 0x0 0x0 0x2 0x1 0x84 0x2 old_data:  addr=None
2024-01-09 17:10:45,366 DEBUG logging:103 Processing: 0x0 0xd 0x0 0x0 0x0 0x2 0x1 0x84 0x2
2024-01-09 17:10:45,366 DEBUG logging:103 Factory Response[132]
*************** data:  b'\x84'
*************** response:  Exception Response(132, 4, IllegalFunction)
2024-01-09 17:10:45,366 ERROR logging:115 General exception: index out of range
2024-01-09 17:10:45,366 DEBUG logging:103 Resetting frame - Current Frame in buffer - 0x0 0xd 0x0 0x0 0x0 0x2 0x1 0x84 0x2
Fatal error: protocol.data_received() call failed.
protocol: <pymodbus.client.tcp.AsyncModbusTcpClient object at 0x7f2f1aac8e90>
transport: <_SelectorSocketTransport fd=6 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib/python3.11/asyncio/selector_events.py", line 1009, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/home/alex/.local/lib/python3.11/site-packages/pymodbus/transport/transport.py", line 312, in data_received
    self.datagram_received(data, None)
  File "/home/alex/.local/lib/python3.11/site-packages/pymodbus/transport/transport.py", line 346, in datagram_received
    cut = self.callback_data(self.recv_buffer, addr=addr)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/alex/.local/lib/python3.11/site-packages/pymodbus/client/base.py", line 186, in callback_data
    self.framer.processIncomingPacket(data, self._handle_response, slave=0)
  File "/home/alex/.local/lib/python3.11/site-packages/pymodbus/framer/base.py", line 139, in processIncomingPacket
    self.frameProcessIncomingPacket(single, callback, slave, **kwargs)
  File "/home/alex/.local/lib/python3.11/site-packages/pymodbus/framer/socket_framer.py", line 147, in frameProcessIncomingPacket
    self._process(callback, tid)
  File "/home/alex/.local/lib/python3.11/site-packages/pymodbus/framer/socket_framer.py", line 158, in _process
    raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request
2024-01-09 17:10:45,367 DEBUG logging:103 Connection lost comm due to Modbus Error: [Input/Output] Unable to decode request
2024-01-09 17:10:45,367 DEBUG logging:103 Getting transaction 13
2024-01-09 17:10:45,368 DEBUG logging:103 Wait comm 100.0 ms before reconnecting.
Traceback (most recent call last):
  File "/home/alex/homeassistant-sungrow/custom_components/sungrow/core/modbus.py", line 325, in _read_range
    rr = await self._client.read_input_registers(address_start - 1, count=address_count, slave=self._slave)  # type: ignore
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/alex/.local/lib/python3.11/site-packages/pymodbus/client/base.py", line 167, in async_execute
    resp = await asyncio.wait_for(
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/asyncio/tasks.py", line 479, in wait_for
    return fut.result()
           ^^^^^^^^^^^^
pymodbus.exceptions.ConnectionException: Modbus Error: [Connection] Connection lost during request

janiversen commented 7 months ago

Let's start by the basic, the mdap header (first 7 bytes) says the data length is 2, and you receive 84 02.... why do you think you only receive 84 ?

A modbus package is minimum 2 byte (funcion code and data byte).

janiversen commented 7 months ago

But anyhow if the code change solve your problem, then please submit a pull request so other can benefit from it.

I am still wondering why wireshark says it is a malformed mode tcp-packet, that seems to be another problem.

AlexanderLanin commented 7 months ago

@janiversen Unfortunately I have no idea about modbus, but I followed the data a little following your 2 byte hint.

The second byte is truncated here (error = False): https://github.com/pymodbus-dev/pymodbus/blob/6913e9c829009f3704f75d7cb7fff019c27c6770/pymodbus/framer/socket_framer.py#L144

So a totally different code change that fixes my problem is deleting the - 1 from those two lines: https://github.com/pymodbus-dev/pymodbus/blob/6913e9c829009f3704f75d7cb7fff019c27c6770/pymodbus/framer/socket_framer.py#L99 https://github.com/pymodbus-dev/pymodbus/blob/6913e9c829009f3704f75d7cb7fff019c27c6770/pymodbus/framer/socket_framer.py#L80

By doing that, I get an IllegalAddress instead of an IllegalFunction which does sound even better. But I have no idea what deleting the - 1 breaks.

janiversen commented 7 months ago

I will take a closer look later this week, I can easily simulate the wireshark packet.

AlexanderLanin commented 7 months ago

P.S. I mentioned the data is only 0x84. That's what I get looking at data in _helper. That's because in the debug log above self._buffer is printed. However, as you see in the code above, self._buffer is not being used! It's using the value from getFrame().

janiversen commented 7 months ago

Solved in #1925

pymodbus-dev / pymodbus