search

pymodbus-dev / pymodbus

A full modbus protocol written in python
Other
2.16k stars 891 forks source link

Decoder exceptions ufter updating 3.4.3->3.6.4 using server #2018

Closed IgorVDubov closed 4 months ago

IgorVDubov commented 4 months ago

Versions

Pymodbus Specific

Description

First, great thanks fot that product!!

In my project I use sevetal conponents wiht pymodbus one read data from sources, process it and exports through MBServer another read it, send to UI and so on. All worked at 3.4.3 for several month till I try to update to latest ver 3.6.4 so MB Server sometimes begin to rise 'Unknown exception "unpack requires a buffer of 4 bytes" on stream server forcing disconnect' so I repeat update step by step from 3.4.3 to trace beginning of problem it begins from 3.6.2->3.63 update exception is rising here: https://github.com/pymodbus-dev/pymodbus/blob/b4490abcfbc5b02e30e1d219b02d6c066ed7de88/pymodbus/register_read_message.py#L43-L48 debug shows that data is 5 bytes sometimes maybe it related to "solve Socket_framer problem with Exception response (#1925)" I view logs and see strange packets like this: 2024-02-14 17:35:57,574 MainThread DEBUG logging :103 Processing: 0x8 0xa4 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2
Is it correct? when process such packet socet framer send 5 bytes data to decoder from here: https://github.com/pymodbus-dev/pymodbus/blob/b4490abcfbc5b02e30e1d219b02d6c066ed7de88/pymodbus/framer/socket_framer.py#L145-L146 and self.getFrame() frame length is what was changed at 3.6.3 (#1925)

Here is log part of 3.6.3 with 2024-02-14 17:35:57,355 - normal packet 2024-02-14 17:35:57,574 - ''double'' packet 2024-02-14 17:35:58,305 - next normal packet

Code and Logs


2024-02-14 17:35:57,355 MainThread      DEBUG    logging        :103      Processing: 0xf 0x3b 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x0 0x2
2024-02-14 17:35:57,356 MainThread      DEBUG    logging        :103      Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-14 17:35:57,356 MainThread      DEBUG    logging        :103      Getting transaction 3899
2024-02-14 17:35:57,356 MainThread      DEBUG    logging        :103      send: 0xf 0x3c 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x0 0x0 0x1
2024-02-14 17:35:57,357 MainThread      DEBUG    logging        :103      Adding transaction 3900
2024-02-14 17:35:57,371 MainThread      DEBUG    logging        :103      recv: 0xf 0x3c 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x0 old_data:  addr=None
2024-02-14 17:35:57,372 MainThread      DEBUG    logging        :103      Processing: 0xf 0x3c 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x0
2024-02-14 17:35:57,372 MainThread      DEBUG    logging        :103      Factory Response[ReadCoilsResponse': 1]
2024-02-14 17:35:57,372 MainThread      DEBUG    logging        :103      Getting transaction 3900
2024-02-14 17:35:57,573 MainThread      DEBUG    logging        :103      recv: 0x8 0xa4 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 old_data:  addr=None
2024-02-14 17:35:57,574 MainThread      DEBUG    logging        :103      Handling data: 0x8 0xa4 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2    
2024-02-14 17:35:57,574 MainThread      DEBUG    logging        :103      Processing: 0x8 0xa4 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2       
2024-02-14 17:35:57,574 MainThread      DEBUG    logging        :103      Factory Request[ReadHoldingRegistersRequest': 3]
exception at framer _process decode call: unpack requires a buffer of 4 bytes
exception att framer _process decode call: b'\x03\x00\x16\x00\x02\x08'
2024-02-14 17:35:57,575 MainThread      DEBUG    logging        :103      Resetting frame - Current Frame in buffer - 0x8 0xa4 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2
exception at processIncomingPacket: Modbus Error: [Input/Output] Unable to decode request       
exception at processIncomingPacket data: b'\x08\xa4\x00\x00\x00\x06\x01\x03\x00\x16\x00\x02\x08\xa3\x00\x00\x00\x06\x01\x03\x00\x16\x00\x02'
exception at processIncomingPacket slave: [1]
2024-02-14 17:35:57,605 MainThread      DEBUG    logging        :103      recv: 0x8 0xa5 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa6 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 old_data:  addr=None
2024-02-14 17:35:57,606 MainThread      DEBUG    logging        :103      Handling data: 0x8 0xa5 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa6 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2    
2024-02-14 17:35:57,606 MainThread      DEBUG    logging        :103      Processing: 0x8 0xa5 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa6 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2       
2024-02-14 17:35:57,606 MainThread      DEBUG    logging        :103      Factory Request[ReadHoldingRegistersRequest': 3]
exception at framer _process decode call: unpack requires a buffer of 4 bytes
exception att framer _process decode call: b'\x03\x00\x16\x00\x02\x08'
2024-02-14 17:35:57,607 MainThread      DEBUG    logging        :103      Resetting frame - Current Frame in buffer - 0x8 0xa5 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa6 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2
exception at processIncomingPacket: Modbus Error: [Input/Output] Unable to decode request       
exception at processIncomingPacket data: b'\x08\xa5\x00\x00\x00\x06\x01\x03\x00\x16\x00\x02\x08\xa6\x00\x00\x00\x06\x01\x03\x00\x16\x00\x02'
exception at processIncomingPacket slave: [1]
2024-02-14 17:35:58,305 MainThread      DEBUG    logging        :103      send: 0x6 0x21 0x0 0x0 0x0 0x6 0x1 0x2 0x0 0x0 0x0 0x8
2024-02-14 17:35:58,305 MainThread      DEBUG    logging        :103      Adding transaction 1569
2024-02-14 17:35:58,306 MainThread      DEBUG    logging        :103      send: 0xf 0x3d 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x2
2024-02-14 17:35:58,306 MainThread      DEBUG    logging        :103      Adding transaction 3901
2024-02-14 17:35:58,307 MainThread      DEBUG    logging        :103      setValues[3] address-1: count-2
2024-02-14 17:35:58,308 MainThread      DEBUG    logging        :103      setValues[3] address-5: count-1
2024-02-14 17:35:58,308 MainThread      DEBUG    logging        :103      setValues[3] address-17: count-2
2024-02-14 17:35:58,308 MainThread      DEBUG    logging        :103      setValues[3] address-19: count-2
2024-02-14 17:35:58,308 MainThread      DEBUG    logging        :103      setValues[3] address-21: count-2
2024-02-14 17:35:58,308 MainThread      DEBUG    logging        :103      setValues[3] address-23: count-2
2024-02-14 17:35:58,309 MainThread      DEBUG    logging        :103      setValues[3] address-25: count-2
2024-02-14 17:35:58,320 MainThread      DEBUG    logging        :103      recv: 0xf 0x3d 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x0 0x0 0x0 0x98 old_data:  addr=None
2024-02-14 17:35:58,320 MainThread      DEBUG    logging        :103      Processing: 0xf 0x3d 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x0 0x0 0x0 0x98
2024-02-14 17:35:58,320 MainThread      DEBUG    logging        :103      Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-14 17:35:58,322 MainThread      DEBUG    logging        :103      Getting transaction 3901
janiversen commented 4 months ago

At a first glance the packet you receive looks ok, let me add it to our test cases and see what happens.

janiversen commented 4 months ago

You have strange overlapping calls:

send: 0xf 0x3c 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x0 0x0 0x1
2024-02-14 17:35:57,357 MainThread      DEBUG    logging        :103      Adding transaction 3900
2024-02-14 17:35:57,371 MainThread      DEBUG    logging        :103      recv: 0xf 0x3c 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x0 old_data:  addr=None
2024-02-14 17:35:57,372 MainThread      DEBUG    logging        :103      Processing: 0xf 0x3c 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x0
2024-02-14 17:35:57,372 MainThread      DEBUG    logging        :103      Factory Response[ReadCoilsResponse': 1]

Here you do a read_coils and get a response.

But then:

2024-02-14 17:35:57,372 MainThread      DEBUG    logging        :103      Getting transaction 3900
2024-02-14 17:35:57,573 MainThread      DEBUG    logging        :103      recv: 0x8 0xa4 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 old_data:  addr=None

You get a response from a read_holding, which was issued much earlier (transaction 0x8 0xa4 version 0xf 0x3c)

Please make a short code part that isolates the problem, then I can simulate it.

If you cannot make a short code example, then I need to see the code where you call pymodbus together with a full log (until the problem occurs).

janiversen commented 4 months ago

I just analyzed the frame that causes the problems:

 recv: 0x8 0xa4 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 old_data:  addr=None

The MBAP header says length = 0x0 0x6 and 0x1 which is slave=1, the response is:

0x3 0x0 0x16 0x0 0x2 0x8

Funcion = 0x3, length in bytes = 0x0, and then 2 registers (4 bytes). So your device responds with a wrong count.

The next frame have a corrupted MBAP header (missing 1 byte) and the response again have byte count = 0, but there are 4 bytes.

This can happen because you have overlapping calls, a lot of devices do not support that. And between 3.4.1 and 3.6.2 we added a faster transport, that might be the reason why you see it. Between 3.6.2 and 3.6.4 we corrected the length, but that does not really affect your problem, since the packets we receive are wrong.

IgorVDubov commented 4 months ago

You get a response from a read_holding, which was issued much earlier (transaction 0x8 0xa4 version 0xf 0x3c)

may be that is because (as I wrote upper) in my project one task reads devices and another task is Modbus Server that responce requests from client. and in logs all recieves and sends are mixed The exception rises at Server task

recv: 0x8 0xa4 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 0x8 0xa3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 old_data: addr=None

may be it is wrong, but as i see we get 2 frames here: 0x8 0xa4 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 + 0x8 0xa3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x16 0x0 0x2 and length is ok - 0x0 0x6 bytes: 0x1 (unit) + 0x3(func) + 0x0 0x16(addr) + 0x0 0x2(reg count) so data culculates by https://github.com/pymodbus-dev/pymodbus/blob/b4490abcfbc5b02e30e1d219b02d6c066ed7de88/pymodbus/framer/socket_framer.py#L145-L146 must be 0x3 0x0 0x16 0x0 0x2

but decoder receives 0x3 0x0 0x16 0x0 0x2 0x8 (+ first byte of next transuction number)

this exception is rare and I haven't stable conditions to repeate it now (just working on it).

janiversen commented 4 months ago

The MBAP header is 7 bytes, and the length = 0x0 0x06, giving a packet length 0f 13 bytes.

length = 6 is 0x3 0x0 0x16 0x0 0x2 0x8, remark a register is 2 bytes there are 2 registers in the response.

0x3 0x0 0x16 0x0 0x2, is not a valid response, because registers are always 2 bytes so it missed a byte.

It is correct it looks a lot like the device did not send the last byte and instead started a new packet....but that is a device problem.

This response is <byte length * 2>....data (2 bytes for each register) byte length = 0, but should be 2. This is a device problem.

So in total it seems your device have 2 problems: 1) it sometimes do not set byte count correctly. 2) it sometimes drop a byte or sends a malformed package.

both problems are outside our control.

IgorVDubov commented 4 months ago

Sorry I can't understand why you don't count Unit identifier byte in length? protocol wiki says that length is "Number of remaining bytes in this frame" and i think that coutung begins from Unit ID byte...

In my case i dont read device here, Modbus server receive read data request (and we see receive log string) from another programm that use pymodbus too to read data from it

janiversen commented 4 months ago

You are right, the length is the remaining data, but Unit identifier is part of the MBAP header, if you do not believe me then please read the the standard.

Anyhow second problem is in the frame itself, where byte count is wrong.

janiversen commented 4 months ago

the log must be from a pymodbus client, because you see a request being sent, the server sends responses. Your last sentence is very confusing, please clarify exactly from where is the log.

And you were right that the unit identifier is not part of the header, but the frame is even more wrong:

So in any case the frame is wrong ! and pymodbus correctly identifies that.

janiversen commented 4 months ago

please be a bit more specific about from where the log comes, I think there are a number of misunderstandings here (and it might be my misunderstandings).

And I also think I need a bit more log, so I can follow the flow. If the log is from a pymodbus server and the client is also pymodbus, then please provide both logs so it's possible to follow a complete flow.

IgorVDubov commented 4 months ago

Thanks for reply misunderstandings is because my programm have modbus reader loop and working modbus server at one event loop and logs are from both. I try to switch off reader section and repeat exception only with modbus server running and provide logs

IgorVDubov commented 4 months ago

This are separate programs: pymodbus reader and pymodbus server with their own logs I try to simulate equal conditions (but different regs was reading) the exception rising in 3.6.4 when program have mass regs reading (when updating all regs several times simultaneously) 3.6.2 do this with no exception...

I joined logs in order to sea processes in conjunction

so, I put here 2 logs first from v3.6.2 wich works fine next from v3.6.4 wich throu exception I only reinstall pymodbus versions - nothing else change

3.6.2 normal work

------------  reader  ------------------
2024-02-20 19:00:45,471    send: 0x0 0x3c 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2
2024-02-20 19:00:45,471    Adding transaction 60
2024-02-20 19:00:45,471    send: 0x0 0x3d 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2
2024-02-20 19:00:45,471    Adding transaction 61
2024-02-20 19:00:45,471    send: 0x0 0x3e 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2
2024-02-20 19:00:45,472    Adding transaction 62
2024-02-20 19:00:45,472    send: 0x0 0x3f 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2
2024-02-20 19:00:45,472    Adding transaction 63

------------  server  ------------------
2024-02-20 19:00:45,472    recv: 0x0 0x3c 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2 0x0 0x3d 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2 0x0 0x3e 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2 0x0 0x3f 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2 old_data:  addr=None
2024-02-20 19:00:45,473    Handling data: 0x0 0x3c 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2 0x0 0x3d 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2 0x0 0x3e 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2 0x0 0x3f 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2
2024-02-20 19:00:45,473    Processing: 0x0 0x3c 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2 0x0 0x3d 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2 0x0 0x3e 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2 0x0 0x3f 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x10 0x0 0x2
2024-02-20 19:00:45,473    Factory Request[ReadHoldingRegistersRequest': 3] 
2024-02-20 19:00:45,473    validate: fc-[3] address-17: count-2
2024-02-20 19:00:45,474    getValues: fc-[3] address-17: count-2
2024-02-20 19:00:45,474    send: 0x0 0x3c 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0
2024-02-20 19:00:45,474    Factory Request[ReadHoldingRegistersRequest': 3] 
2024-02-20 19:00:45,474    validate: fc-[3] address-17: count-2
2024-02-20 19:00:45,474    getValues: fc-[3] address-17: count-2
2024-02-20 19:00:45,474    send: 0x0 0x3d 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0
2024-02-20 19:00:45,475    Factory Request[ReadHoldingRegistersRequest': 3] 
2024-02-20 19:00:45,475    validate: fc-[3] address-17: count-2
2024-02-20 19:00:45,475    getValues: fc-[3] address-17: count-2
2024-02-20 19:00:45,475    send: 0x0 0x3e 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0
2024-02-20 19:00:45,475    Factory Request[ReadHoldingRegistersRequest': 3] 
2024-02-20 19:00:45,475    validate: fc-[3] address-17: count-2
2024-02-20 19:00:45,476    getValues: fc-[3] address-17: count-2
2024-02-20 19:00:45,476    send: 0x0 0x3f 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0

------------  reader  ------------------  
2024-02-20 19:00:45,475    recv: 0x0 0x3c 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0 0x0 0x3d 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0 old_data:  addr=None
2024-02-20 19:00:45,475    Processing: 0x0 0x3c 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0 0x0 0x3d 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0
2024-02-20 19:00:45,475    Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-20 19:00:45,475    Getting transaction 60
2024-02-20 19:00:45,475    Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-20 19:00:45,476    Getting transaction 61
2024-02-20 19:00:45,476    recv: 0x0 0x3e 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0 old_data:  addr=None
2024-02-20 19:00:45,476    Processing: 0x0 0x3e 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0
2024-02-20 19:00:45,476    Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-20 19:00:45,476    Getting transaction 62
2024-02-20 19:00:45,477    send: 0x0 0x42 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x14 0x0 0x2
2024-02-20 19:00:45,477    Adding transaction 66
2024-02-20 19:00:45,477    send: 0x0 0x43 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x14 0x0 0x2
2024-02-20 19:00:45,477    Adding transaction 67
2024-02-20 19:00:45,477    recv: 0x0 0x3f 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0 0x0 0x40 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x0 0x0 0x0 0xb old_data:  addr=None
2024-02-20 19:00:45,478    Processing: 0x0 0x3f 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x41 0xb0 0x0 0x0 0x0 0x40 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x0 0x0 0x0 0xb
2024-02-20 19:00:45,478    Factory Response[ReadHoldingRegistersResponse': 3]

3.6.4 exception rising

------------  reader  ------------------
2024-02-20 18:10:43,637    Adding transaction 75    
2024-02-20 18:10:43,637    send: 0x0 0x4b 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x2
2024-02-20 18:10:43,637    Adding transaction 76    
2024-02-20 18:10:43,637    send: 0x0 0x4c 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x2
2024-02-20 18:10:43,637    Adding transaction 77    
2024-02-20 18:10:43,637    send: 0x0 0x4d 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x12 0x0 0x2

------------  server  ------------------
2024-02-20 18:10:43,638    recv: 0x0 0x4b 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x2 0x0 0x4c 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x2 0x0 0x4d 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x12 0x0 0x2 old_data:  addr=None
2024-02-20 18:10:43,638    Handling data: 0x0 0x4b 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x2 0x0 0x4c 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x2 0x0 0x4d 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x12 0x0 0x2
2024-02-20 18:10:43,639    Processing: 0x0 0x4b 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x2 0x0 0x4c 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x2 0x0 0x4d 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x12 0x0 0x2
2024-02-20 18:10:43,639    Factory Request[ReadHoldingRegistersRequest': 3]
2024-02-20 18:10:43,639 MainThread      ERROR    logging        :115      Unknown exception "unpack requires a buffer of 4 bytes" on stream server forcing disconnect
2024-02-20 18:10:43,639    Client Disconnection server due to unpack requires a buffer of 4 bytes

------------  reader  ------------------
2024-02-20 18:10:43,638    recv: 0x0 0x49 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x42 0xf0 0x0 0x0 old_data:  addr=None
2024-02-20 18:10:43,638    Processing: 0x0 0x49 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x42 0xf0 0x0 0x0
2024-02-20 18:10:43,638    Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-20 18:10:43,638    Getting transaction 73   
2024-02-20 18:10:43,638    Frame check failed, ignoring!!
2024-02-20 18:10:43,639    recv: 0x0 0x4a 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x42 0x70 0x0 0x0 old_data:  addr=None
2024-02-20 18:10:43,639    Processing: 0x0 0x4a 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x42 0x70 0x0 0x0
2024-02-20 18:10:43,639    Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-20 18:10:43,639    Getting transaction 74   
2024-02-20 18:10:43,639    Frame check failed, ignoring!!
2024-02-20 18:10:43,639    Adding transaction 78    
2024-02-20 18:10:43,640    send: 0x0 0x4e 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x12 0x0 0x2
2024-02-20 18:10:43,640    Adding transaction 79    
2024-02-20 18:10:43,640    send: 0x0 0x4f 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x2
2024-02-20 18:10:43,640    Connection lost comm due to [WinError 10053] 
2024-02-20 18:10:43,640    callback_disconnected called: [WinError 10053]    
2024-02-20 18:10:43,641    Wait comm 100.0 ms before reconnecting.
2024-02-20 18:10:43,756    Connecting comm

------------  server  ------------------
2024-02-20 18:10:43,758    Connected to server

------------  reader  ------------------
2024-02-20 18:10:43,758    Connected to comm        
2024-02-20 18:10:43,758    callback_connected called
2024-02-20 18:10:44,785    Adding transaction 80
2024-02-20 18:10:44,785    send: 0x0 0x50 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x18 0x0 0x2
janiversen commented 4 months ago

Thanks it look ore understandable, I have a closer look but not today

janiversen commented 4 months ago

A couple of observations, about the 3.6.4 logs: 1) It seems reader transmits the 3 requests as one package, while legal, it looks like you have overlapping request calls which might lead to other problems. 2) the server clearly have a problem decoding the sequence, which I will simulate. 3) The second reader log then receives data, that the server did not send ???? Seems you left out a couple of lines from the beginning of the server log, showing the send. 4) I cannot see why you get "frame check failing" because I cannot see what reader sends and then what server sends.

If you still have the logs, please amend first reader, with the send that caused the Frame check failure when returned, and please amend first server, with the receive of the request that leads to the frame check failure.

IgorVDubov commented 4 months ago

ok, I make test stands from client and server examples and find out when 3.6.4. begins to throw exception: when time between request sends are very small - I reached it by running read_register tasks using asyncio.gather. Here is reader and server 3.6.4 rise Unknown exception "unpack requires a buffer of 4 bytes" on stream server forcing disconnect if N>2 at reader and message "Frame check failed, ignoring!!" is always too if I read regs not gathering read tasks - it works. 3.6.2 works gathering read tasks with N=500 with no exceptions and check failed messages You can try to test it

server:

import logging
FORMAT = ('%(asctime)-15s  %(message)s')
logging.basicConfig(format=FORMAT)
log = logging.getLogger()
log.setLevel(logging.DEBUG)

from pymodbus.datastore import (ModbusSequentialDataBlock, ModbusServerContext,
                                ModbusSlaveContext)
from pymodbus.server.async_io import  StartTcpServer
from threading import Thread
import time

def updating_writer(con):
    time.sleep(1)
    context = con['con']
    context[0].setValues(3, 0, [777])

def run_server():
    store = ModbusSlaveContext(
        hr=ModbusSequentialDataBlock(0, [3]*1)
        )
    context = ModbusServerContext(slaves=store, single=True)
    updating_writer_thread = Thread(target = updating_writer, args = [{'con':context}])    
    updating_writer_thread.daemon=True
    updating_writer_thread.start()

    StartTcpServer(context=context, address=("127.0.0.1", 5021))

if __name__ == "__main__":
    run_server()

reader:

from pymodbus.client.tcp import AsyncModbusTcpClient
import asyncio
import logging
FORMAT = ('%(asctime)-15s  %(message)s')
logging.basicConfig(format=FORMAT)
log = logging.getLogger()
log.setLevel(logging.DEBUG)

N = 3

async def main():
    c = AsyncModbusTcpClient('127.0.0.1', 5021)
    await c.connect()
    tasks = []
    for _ in range(N):    
        tasks.append(c.read_holding_registers(0, 1, 1))
        # r = await c.connection.read_holding_registers(0, 1, 1)
    read_result = await asyncio.gather(*tasks)        
    for i, r in enumerate(read_result):    
        print(f'result {i}: {r.registers}')

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

full logs of 3.6.4

server
2024-02-21 19:30:24,114  Using proactor: IocpProactor
2024-02-21 19:30:24,117  Awaiting connections server_listener
2024-02-21 19:30:24,117  Server listening.
2024-02-21 19:30:25,116  setValues[3] address-1: count-1
2024-02-21 19:30:35,290  Connected to server
2024-02-21 19:30:35,291  recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 old_data:  addr=None
2024-02-21 19:30:35,291  Handling data: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:30:35,291  Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:30:35,292  Factory Request[ReadHoldingRegistersRequest': 3]
2024-02-21 19:30:35,292  validate: fc-[3] address-1: count-1
2024-02-21 19:30:35,292  getValues: fc-[3] address-1: count-1
2024-02-21 19:30:35,292  send: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:30:35,293  Frame check failed, ignoring!!
2024-02-21 19:30:35,293  recv: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 old_data:  addr=None
2024-02-21 19:30:35,293  Handling data: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:30:35,294  Processing: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:30:35,294  Factory Request[ReadHoldingRegistersRequest': 3]
2024-02-21 19:30:35,294  Unknown exception "unpack requires a buffer of 4 bytes" on stream server forcing disconnect
2024-02-21 19:30:35,294  Client Disconnection server due to unpack requires a buffer of 4 bytes
2024-02-21 19:30:35,411  Connected to server
2024-02-21 19:30:38,297  recv: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 old_data:  addr=None
2024-02-21 19:30:38,297  Handling data: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1     
2024-02-21 19:30:38,297  Processing: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1        
2024-02-21 19:30:38,297  Factory Request[ReadHoldingRegistersRequest': 3]
2024-02-21 19:30:38,298  validate: fc-[3] address-1: count-1
2024-02-21 19:30:38,298  getValues: fc-[3] address-1: count-1
2024-02-21 19:30:38,298  send: 0x0 0x3 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:30:38,298  Frame check failed, ignoring!!
2024-02-21 19:30:38,298  recv: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 old_data:  addr=None
2024-02-21 19:30:38,299  Handling data: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1     
2024-02-21 19:30:38,299  Processing: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1        
2024-02-21 19:30:38,299  Factory Request[ReadHoldingRegistersRequest': 3]
2024-02-21 19:30:38,299  validate: fc-[3] address-1: count-1
2024-02-21 19:30:38,299  getValues: fc-[3] address-1: count-1
2024-02-21 19:30:38,300  send: 0x0 0x2 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:30:38,300  Frame check failed, ignoring!!
2024-02-21 19:30:38,311  -> transport: received eof
2024-02-21 19:30:38,311  Connection lost server due to None
2024-02-21 19:30:38,311  Handler for stream [server] has been canceled
reader
2024-02-21 19:30:35,288  Using proactor: IocpProactor                                      
2024-02-21 19:30:35,289  Connecting to 127.0.0.1:5021.
2024-02-21 19:30:35,289  Connecting comm
2024-02-21 19:30:35,289  Connected to comm
2024-02-21 19:30:35,289  callback_connected called
2024-02-21 19:30:35.289 | INFO     | gathercore.modbusconnector:start:86 - Client ip=127.0.0.1:5021 starts. Connection is True
2024-02-21 19:30:35,291  Adding transaction 1
2024-02-21 19:30:35,291  send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:30:35,291  Adding transaction 2
2024-02-21 19:30:35,291  send: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:30:35,291  Adding transaction 3
2024-02-21 19:30:35,291  send: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:30:35,293  recv: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9 old_data:  addr=None
2024-02-21 19:30:35,293  Processing: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:30:35,293  Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-21 19:30:35,293  Getting transaction 1
2024-02-21 19:30:35,293  Frame check failed, ignoring!!
2024-02-21 19:30:35,295  -> transport: received eof
2024-02-21 19:30:35,295  Connection lost comm due to None
2024-02-21 19:30:35,295  callback_disconnected called: None
2024-02-21 19:30:35,295  Wait comm 100.0 ms before reconnecting.
2024-02-21 19:30:35,410  Connecting comm
2024-02-21 19:30:35,411  Connected to comm
2024-02-21 19:30:35,411  callback_connected called
2024-02-21 19:30:38,296  Adding transaction 3
2024-02-21 19:30:38,296  send: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:30:38,296  Adding transaction 2
2024-02-21 19:30:38,297  send: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:30:38,298  recv: 0x0 0x3 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9 old_data:  addr=None
2024-02-21 19:30:38,298  Processing: 0x0 0x3 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:30:38,299  Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-21 19:30:38,299  Getting transaction 3
2024-02-21 19:30:38,299  Frame check failed, ignoring!!
2024-02-21 19:30:38,300  recv: 0x0 0x2 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9 old_data:  addr=None
2024-02-21 19:30:38,300  Processing: 0x0 0x2 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:30:38,300  Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-21 19:30:38,300  Getting transaction 2
2024-02-21 19:30:38,300  Frame check failed, ignoring!!
result 0: [777]
result 1: [777]
result 2: [777]

logs from 3.6.2

server
3.6.2
2024-02-21 19:52:20,824  Using proactor: IocpProactor
2024-02-21 19:52:20,829  Awaiting connections server_listener
2024-02-21 19:52:20,830  Server listening.
2024-02-21 19:52:21,826  setValues[3] address-1: count-1
2024-02-21 19:52:29,510  Connected to server
2024-02-21 19:52:29,511  recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 old_data:  addr=None
2024-02-21 19:52:29,511  Handling data: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:52:29,511  Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:52:29,512  Factory Request[ReadHoldingRegistersRequest': 3]
2024-02-21 19:52:29,512  validate: fc-[3] address-1: count-1
2024-02-21 19:52:29,512  getValues: fc-[3] address-1: count-1
2024-02-21 19:52:29,512  send: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:52:29,513  recv: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 old_data:  addr=None
2024-02-21 19:52:29,513  Handling data: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:52:29,514  Processing: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:52:29,514  Factory Request[ReadHoldingRegistersRequest': 3]
2024-02-21 19:52:29,514  validate: fc-[3] address-1: count-1
2024-02-21 19:52:29,514  getValues: fc-[3] address-1: count-1
2024-02-21 19:52:29,514  send: 0x0 0x2 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:52:29,514  Factory Request[ReadHoldingRegistersRequest': 3]
2024-02-21 19:52:29,515  validate: fc-[3] address-1: count-1
2024-02-21 19:52:29,515  getValues: fc-[3] address-1: count-1
2024-02-21 19:52:29,515  send: 0x0 0x3 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:52:29,526  -> transport: received eof
2024-02-21 19:52:29,526  Connection lost server due to None
2024-02-21 19:52:29,526  Handler for stream [server] has been canceled
reader
2024-02-21 19:52:29,508  Using proactor: IocpProactor                                      
2024-02-21 19:52:29,509  Connecting to 127.0.0.1:5021.
2024-02-21 19:52:29,509  Connecting comm
2024-02-21 19:52:29,509  Connected to comm
2024-02-21 19:52:29,509  callback_connected called
2024-02-21 19:52:29.509 | INFO     | gathercore.modbusconnector:start:86 - Client ip=127.0.0.1:5021 starts. Connection is True
2024-02-21 19:52:29,510  send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:52:29,510  Adding transaction 1
2024-02-21 19:52:29,510  send: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:52:29,511  Adding transaction 2
2024-02-21 19:52:29,511  send: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x0 0x0 0x1
2024-02-21 19:52:29,511  Adding transaction 3
2024-02-21 19:52:29,513  recv: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9 old_data:  addr=None
2024-02-21 19:52:29,513  Processing: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:52:29,513  Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-21 19:52:29,513  Getting transaction 1
2024-02-21 19:52:29,514  recv: 0x0 0x2 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9 old_data:  addr=None
2024-02-21 19:52:29,515  Processing: 0x0 0x2 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:52:29,515  Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-21 19:52:29,515  Getting transaction 2
2024-02-21 19:52:29,516  recv: 0x0 0x3 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9 old_data:  addr=None
2024-02-21 19:52:29,516  Processing: 0x0 0x3 0x0 0x0 0x0 0x5 0x1 0x3 0x2 0x3 0x9
2024-02-21 19:52:29,516  Factory Response[ReadHoldingRegistersResponse': 3]
2024-02-21 19:52:29,516  Getting transaction 3
result 0: [777]
result 1: [777]
result 2: [777]
IgorVDubov commented 4 months ago

sorry, in reader I imported client from my project AsyncModbusClient.connection = pymodbus.client.tcp.AsyncModbusTcpClient

P.S. correct previous comment to use only pymodbus lib

janiversen commented 4 months ago

Hmmm that is very good hint, let me build that into the simulation of your bug.