Decoder exceptions ufter updating 3.4.3->3.6.4 using server

[IgorVDubov]

Versions

• Python: 3.11
• OS: Windows 11
• Pymodbus: 3.6.4
• Modbus Hardware (if used): -

Pymodbus Specific

• Server: tcp/async
• Client: tcp/async

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:

pymodbus/pymodbus/register_read_message.py

Lines 43 to 48 in b4490ab

	def decode(self, data):
	"""Decode a register request packet.
	:param data: The request to decode
	"""
	self.address, self.count = struct.unpack(">HH", data)

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:

pymodbus/pymodbus/framer/socket_framer.py

Lines 145 to 146 in b4490ab

	data = self._buffer if error else self.getFrame()
	if (result := self.decoder.decode(data)) is None:

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]

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

[janiversen]

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]

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]

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

pymodbus/pymodbus/framer/socket_framer.py

Lines 145 to 146 in b4490ab

	data = self._buffer if error else self.getFrame()
	if (result := self.decoder.decode(data)) is None:

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]

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]

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]

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]

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:

• byte count is 0, but there are registers.
• data part is 3 bytes, which is not allowed it must be an even number.

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

[janiversen]

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]

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]

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