Modbus slave transaction handling on open connection becomes mangled when multiple transactions are handled concurrently (EPROT-55)

[blank-lgtm]

Checklist

• Checked the issue tracker for similar issues to ensure this is not a duplicate
• Read the documentation to confirm the issue is not addressed there and your configuration is set correctly
• Tested with the latest version to ensure the issue hasn't been fixed

How often does this bug occurs?

rarely

Expected behavior

When device running modbus receives multiple transactions between multiple open connections each transaction should be processed in its entirety.

Actual behavior (suspected bug)

When a device receives a modbus request while in a specific section of processing a previous transaction, the device may abandon processing the original transaction in favor of the new request. This partially processed transaction will finish and a reply is generated only on next transaction receive where the newly received transaction will become suspended in the same way. This corrupted state persists until the affected connection socket is closed by peer.

Error logs or terminal output

D (42951) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_open: fd: 1
D (42951) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_connect: fd: 1
D (43001) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_recv_data: fd: 0
D (43001) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55) [192.168.100.1], receive data ready.
D (43001) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), received packet TID: 0x001d, frame: 0x3fcba618, 12
D (43021) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x001d, start transaction.
D (43031) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x001d.
D (43041) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_recv_data: fd: 1
D (43041) mb_port.tcp.slave: 0x3fcb5c14, node #1, socket(#56) [192.168.100.1], receive data ready.
D (43051) mb_port.tcp.slave: 0x3fcb5c14, node #1, socket(#56)(192.168.100.1), received packet TID: 0x0001, frame: 0x3fcba638, 12
D (43071) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43071) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43081) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43081) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43091) mb_port.tcp.slave: 0x3fcb59d8, node #0, socket(#55)(192.168.100.1), read packet, TID: 0x001d, 0x3fcb5764.
D (43101) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_send_data: fd: 0
D (43111) mb_port.tcp.slave: 0x3fcb5c14, node: #0, socket(#55)[192.168.100.1], send packet TID: 0x001d:0x001d, 0x3fcb5764, len: 23, 
D (43121) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), sent packet TID: 0x001d, 0x3fcb9774.
D (43131) mb_port.tcp.slave: Remove the message TID:0x001d
I (43141) SLAVE_TEST: OBJ 0x3fcb4224, HOLDING READ (43106297 us), ADDR:12, TYPE:2, INST_ADDR:0x3fc9f34c, SIZE:7
D (43181) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43181) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43231) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43231) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43281) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43281) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43331) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43331) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43381) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43381) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43431) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43431) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43481) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43481) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43531) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43531) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43581) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43581) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43631) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43631) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43681) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43681) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43731) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43731) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43781) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43781) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43831) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43831) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43881) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43881) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43931) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43931) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (43981) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (43981) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44031) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44031) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44081) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44081) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44131) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_recv_data: fd: 0
D (44131) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55) [192.168.100.1], receive data ready.
D (44131) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), received packet TID: 0x001e, frame: 0x3fcba618, 12
D (44141) mb_port.tcp.slave: 0x3fcb5c14, node #1, socket(#56)(192.168.100.1), acknowledged packet TID: 0x0001, start transaction.
D (44161) mb_port.tcp.slave: 0x3fcb5c14, node #1, socket(#56)(192.168.100.1), acknowledged packet TID: 0x0001.
D (44171) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44171) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44181) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44191) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44191) mb_port.tcp.slave: 0x3fcb59d8, node #1, socket(#56)(192.168.100.1), read packet, TID: 0x0001, 0x3fcb5764.
D (44201) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_send_data: fd: 1
D (44211) mb_port.tcp.slave: 0x3fcb5c14, node: #1, socket(#56)[192.168.100.1], send packet TID: 0x0001:0x0001, 0x3fcb5764, len: 23, 
D (44221) mb_port.tcp.slave: 0x3fcb5c14, node #1, socket(#56)(192.168.100.1), sent packet TID: 0x0001, 0x3fcb9774.
D (44231) mb_port.tcp.slave: Remove the message TID:0x0001
I (44241) SLAVE_TEST: OBJ 0x3fcb4224, HOLDING READ (44208515 us), ADDR:12, TYPE:2, INST_ADDR:0x3fc9f34c, SIZE:7
D (44291) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44291) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44341) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44341) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44391) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44391) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44441) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44441) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44491) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44491) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44541) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44541) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44591) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44591) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44641) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44641) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44691) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44691) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44741) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44741) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44791) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (44791) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44841) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
E (44841) mb_port.tcp.slave: 0x3fcb59d8, node #2, socket(#57)(192.168.100.1), communication fail, err= -11
D (44841) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44901) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (44951) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45001) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45051) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45101) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45151) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45201) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45251) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45251) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45301) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45301) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45351) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45351) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45401) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45401) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45451) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45451) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45501) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45501) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45551) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45551) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45601) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45601) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45651) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45651) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45701) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45701) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45751) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45751) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45801) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45801) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45851) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45851) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45901) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45901) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (45951) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (45951) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46001) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46001) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46051) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46051) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46101) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46101) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46151) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46151) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46201) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46201) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46251) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46251) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46301) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46301) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46351) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46351) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46401) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46401) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46451) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46451) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46501) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46501) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46551) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46551) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46601) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46601) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46651) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46651) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46701) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46701) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46751) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46751) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46801) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46801) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46851) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_open: fd: 2
D (46851) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_connect: fd: 2
D (46901) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46901) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_recv_data: fd: 2
D (46901) mb_port.tcp.slave: 0x3fcb5c14, node #2, socket(#57) [192.168.100.1], receive data ready.
D (46911) mb_port.tcp.slave: 0x3fcb5c14, node #2, socket(#57)(192.168.100.1), received packet TID: 0x0001, frame: 0x3fcba96c, 12
D (46921) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x001e, start transaction.
D (46931) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x001e.
D (46941) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46951) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (46961) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (46961) mb_port.tcp.slave: 0x3fcb59d8, node #0, socket(#55)(192.168.100.1), read packet, TID: 0x001e, 0x3fcb5764.
D (46971) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_send_data: fd: 0
D (46981) mb_port.tcp.slave: 0x3fcb5c14, node: #0, socket(#55)[192.168.100.1], send packet TID: 0x001e:0x001e, 0x3fcb5764, len: 23, 
D (46991) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), sent packet TID: 0x001e, 0x3fcbb938.
D (47001) mb_port.tcp.slave: Remove the message TID:0x001e
I (47011) SLAVE_TEST: OBJ 0x3fcb4224, HOLDING READ (46978483 us), ADDR:12, TYPE:2, INST_ADDR:0x3fc9f34c, SIZE:7
D (47061) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47061) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (47111) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47111) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (47161) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47161) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (47211) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47211) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (47261) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47261) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (47311) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47311) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (47361) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47361) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (47411) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47411) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (47461) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47461) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (47511) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47511) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (47561) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47561) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
D (47611) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47611) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 3
E (47611) mb_port.tcp.slave: 0x3fcb59d8, node #3, socket(#58)(192.168.100.1), communication fail, err= -11
D (47671) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47721) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47771) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47821) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47871) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47921) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (47971) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48021) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_recv_data: fd: 0
D (48021) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55) [192.168.100.1], receive data ready.
D (48021) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), received packet TID: 0x001f, frame: 0x3fcba95c, 12
D (48031) mb_port.tcp.slave: 0x3fcb5c14, node #2, socket(#57)(192.168.100.1), acknowledged packet TID: 0x0001, start transaction.
D (48051) mb_port.tcp.slave: 0x3fcb5c14, node #2, socket(#57)(192.168.100.1), acknowledged packet TID: 0x0001.
D (48061) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48061) mb_port.tcp.slave: 0x3fcb59d8, node #2, socket(#57)(192.168.100.1), read packet, TID: 0x0001, 0x3fcb5764.
D (48071) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_send_data: fd: 2
D (48081) mb_port.tcp.slave: 0x3fcb5c14, node: #2, socket(#57)[192.168.100.1], send packet TID: 0x0001:0x0001, 0x3fcb5764, len: 23, 
D (48091) mb_port.tcp.slave: 0x3fcb5c14, node #2, socket(#57)(192.168.100.1), sent packet TID: 0x0001, 0x3fcb9774.
D (48101) mb_port.tcp.slave: Remove the message TID:0x0001
I (48111) SLAVE_TEST: OBJ 0x3fcb4224, HOLDING READ (48079751 us), ADDR:12, TYPE:2, INST_ADDR:0x3fc9f34c, SIZE:7
D (48161) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48211) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48261) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48311) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48361) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48411) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48461) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48511) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48561) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48611) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48661) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48711) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48761) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48811) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48861) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48911) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (48961) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49011) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49061) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49111) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49111) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49161) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49161) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49211) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49211) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49261) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49261) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49311) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49311) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49361) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49361) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49411) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49411) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49461) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49461) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49511) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49511) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49561) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49561) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49611) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49611) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49661) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49661) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49711) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49711) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49761) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49761) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49811) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49811) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49861) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49861) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49911) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49911) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (49961) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (49961) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50011) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50011) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50061) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50061) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50111) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50111) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50161) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50161) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50211) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50211) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50261) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50261) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50311) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50311) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50361) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50361) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50411) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50411) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50461) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50461) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50511) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50511) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50561) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50561) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50611) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
D (50611) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50661) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 1
E (50661) mb_port.tcp.slave: 0x3fcb59d8, node #1, socket(#56)(192.168.100.1), communication fail, err= -11
D (50661) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50721) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50771) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50821) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50871) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50921) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (50971) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51021) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51071) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51121) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51171) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51221) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51271) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51321) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51371) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51421) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51471) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51521) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51571) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51621) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51671) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51721) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51771) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51821) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51871) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51921) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (51971) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52021) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52071) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52121) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52171) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52221) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52271) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52321) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52371) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52421) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52471) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52521) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52571) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52621) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52671) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52721) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52771) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52821) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52871) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52921) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (52971) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53021) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53071) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53121) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53171) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53221) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53271) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53321) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53371) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53421) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53471) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53521) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53571) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53621) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53671) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53721) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53771) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53821) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53871) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53921) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (53971) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (54021) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_recv_data: fd: 0
D (54021) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55) [192.168.100.1], receive data ready.
D (54021) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), received packet TID: 0x0020, frame: 0x3fcba608, 12
D (54031) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x001f, start transaction.
D (54051) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x001f.
D (54061) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (54061) mb_port.tcp.slave: 0x3fcb59d8, node #0, socket(#55)(192.168.100.1), read packet, TID: 0x0020, 0x3fcb5764.
D (54071) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_send_data: fd: 0
D (54081) mb_port.tcp.slave: 0x3fcb5c14, node: #0, socket(#55)[192.168.100.1], send packet TID: 0x001f:0x001f, 0x3fcb5764, len: 23, 
D (54091) mb_port.tcp.slave: Remove the message TID:0x001f
D (54101) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), frame TID:0x0020!=0x001f, slave is busy.
W (54111) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), handling time [ms]: 6062, exceeds slave response time in master.
I (54121) SLAVE_TEST: OBJ 0x3fcb4224, HOLDING READ (54079700 us), ADDR:12, TYPE:2, INST_ADDR:0x3fc9f34c, SIZE:7
D (54171) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (54221) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (54271) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (54321) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (54371) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (54421) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (54471) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (54521) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
D (54571) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_error: fd: 2
E (54571) mb_port.tcp.slave: 0x3fcb59d8, node #2, socket(#57)(192.168.100.1), communication fail, err= -11
D (54831) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (55091) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (55351) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (55611) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (55871) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (56131) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (56391) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (56651) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (56911) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (57171) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (57431) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (57691) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (57951) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (58211) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (58471) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (58731) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (58991) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (59251) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (59511) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (59771) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (60011) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_recv_data: fd: 0
D (60011) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55) [192.168.100.1], receive data ready.
D (60021) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), received packet TID: 0x0021, frame: 0x3fcba95c, 12
D (60031) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x0020, start transaction.
D (60041) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x0020.
D (60051) mb_port.tcp.slave: 0x3fcb59d8, node #0, socket(#55)(192.168.100.1), read packet, TID: 0x0021, 0x3fcb5764.
D (60061) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_send_data: fd: 0
D (60071) mb_port.tcp.slave: 0x3fcb5c14, node: #0, socket(#55)[192.168.100.1], send packet TID: 0x0020:0x0020, 0x3fcb5764, len: 23, 
D (60081) mb_port.tcp.slave: Remove the message TID:0x0020
D (60081) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), frame TID:0x0021!=0x0020, slave is busy.
W (60091) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), handling time [ms]: 6049, exceeds slave response time in master.
I (60111) SLAVE_TEST: OBJ 0x3fcb4224, HOLDING READ (60066425 us), ADDR:12, TYPE:2, INST_ADDR:0x3fc9f34c, SIZE:7
D (60371) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (60631) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (60891) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (61151) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (61411) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (61671) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (61931) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (62191) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (62451) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (62711) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (62971) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (63231) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (63491) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (63751) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (64011) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (64271) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (64531) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (64791) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (65051) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (65311) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (65571) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (65831) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (66021) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_recv_data: fd: 0
D (66021) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55) [192.168.100.1], receive data ready.
D (66021) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), received packet TID: 0x0022, frame: 0x3fcba608, 12
D (66031) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x0021, start transaction.
D (66051) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x0021.
D (66061) mb_port.tcp.slave: 0x3fcb59d8, node #0, socket(#55)(192.168.100.1), read packet, TID: 0x0022, 0x3fcb5764.
D (66071) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_send_data: fd: 0
D (66071) mb_port.tcp.slave: 0x3fcb5c14, node: #0, socket(#55)[192.168.100.1], send packet TID: 0x0021:0x0021, 0x3fcb5764, len: 23, 
D (66091) mb_port.tcp.slave: Remove the message TID:0x0021
D (66091) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), frame TID:0x0022!=0x0021, slave is busy.
W (66101) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), handling time [ms]: 6064, exceeds slave response time in master.
I (66121) SLAVE_TEST: OBJ 0x3fcb4224, HOLDING READ (66073882 us), ADDR:12, TYPE:2, INST_ADDR:0x3fc9f34c, SIZE:7
D (66381) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (66641) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (66901) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (67161) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (67421) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (67681) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (67941) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (68201) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (68461) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (68721) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (68981) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (69241) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (69501) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (69761) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (70021) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (70281) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (70541) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (70801) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (71061) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (71321) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (71581) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (71841) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (72021) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_recv_data: fd: 0
D (72021) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55) [192.168.100.1], receive data ready.
D (72031) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), received packet TID: 0x0023, frame: 0x3fcba95c, 12
D (72041) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x0022, start transaction.
D (72051) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x0022.
D (72061) mb_port.tcp.slave: 0x3fcb59d8, node #0, socket(#55)(192.168.100.1), read packet, TID: 0x0023, 0x3fcb5764.
D (72071) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_send_data: fd: 0
D (72081) mb_port.tcp.slave: 0x3fcb5c14, node: #0, socket(#55)[192.168.100.1], send packet TID: 0x0022:0x0022, 0x3fcb5764, len: 23, 
D (72091) mb_port.tcp.slave: Remove the message TID:0x0022
D (72101) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), frame TID:0x0023!=0x0022, slave is busy.
W (72111) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), handling time [ms]: 6062, exceeds slave response time in master.
I (72121) SLAVE_TEST: OBJ 0x3fcb4224, HOLDING READ (72079974 us), ADDR:12, TYPE:2, INST_ADDR:0x3fc9f34c, SIZE:7
D (72381) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (72641) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (72901) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (73161) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (73421) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (73681) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (73941) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (74201) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (74461) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (74721) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (74981) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (75241) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (75501) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (75761) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (76021) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (76281) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (76541) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (76801) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (77061) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (77321) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (77581) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (77841) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (78041) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_recv_data: fd: 0
D (78041) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55) [192.168.100.1], receive data ready.
D (78051) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), received packet TID: 0x0024, frame: 0x3fcba608, 12
D (78061) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x0023, start transaction.
D (78071) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x0023.
D (78081) mb_port.tcp.slave: 0x3fcb59d8, node #0, socket(#55)(192.168.100.1), read packet, TID: 0x0024, 0x3fcb5764.
D (78091) mb_port.tcp.slave: loop:0x3fcb5c14  mbs_on_send_data: fd: 0
D (78101) mb_port.tcp.slave: 0x3fcb5c14, node: #0, socket(#55)[192.168.100.1], send packet TID: 0x0023:0x0023, 0x3fcb5764, len: 23, 
D (78111) mb_port.tcp.slave: Remove the message TID:0x0023
D (78111) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), frame TID:0x0024!=0x0023, slave is busy.
W (78121) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), handling time [ms]: 6072, exceeds slave response time in master.
I (78141) SLAVE_TEST: OBJ 0x3fcb4224, HOLDING READ (78095594 us), ADDR:12, TYPE:2, INST_ADDR:0x3fc9f34c, SIZE:7
D (78401) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (78661) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (78921) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (79181) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (79441) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (79701) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (79961) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (80221) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (80481) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1
D (80741) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_timeout: fd: 0, count: 1

Steps to reproduce the behavior

1. build modbus_tcp_slave example
2. run example
3. using a modbus client, open a socket and periodically send a modbus register read request
4. create a second modbus client, send identical register read request with a random period and closing the tcp connection between attempts until requests from both clients align in such a way to generate transaction mangling

Project release version

esp_modbus 2.1.2, esp-idf 5.2.5

System architecture

Intel/AMD 64-bit (modern PC, older Mac)

Operating system

Windows

Operating system version

Windows 11

Shell

PowerShell

Additional context

The state modbus slave enters after the occurrence of the bug is effectively such that it always tries to reply to the previous transaction ID when a new transaction is received. A continuously running modbus server polling the device will start timeouting transactions as the reply will be received only after a new transaction is initiated upon a timeout of the original one.

The log I provided is from the modbus example with only mb_port.tcp.slave tag set to debug to be more concise.

Bug presents itself in log section:

D (44131) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_recv_data: fd: 0
D (44131) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55) [192.168.100.1], receive data ready.
D (44131) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), received packet TID: 0x001e, frame: 0x3fcba618, 12
D (44141) mb_port.tcp.slave: 0x3fcb5c14, node #1, socket(#56)(192.168.100.1), acknowledged packet TID: 0x0001, start transaction.
D (44161) mb_port.tcp.slave: 0x3fcb5c14, node #1, socket(#56)(192.168.100.1), acknowledged packet TID: 0x0001.
D (44171) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_error: fd: 2
D (44171) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_error: fd: 3
D (44181) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_error: fd: 2
D (44191) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_error: fd: 3
D (44191) mb_port.tcp.slave: 0x3fcb59d8, node #1, socket(#56)(192.168.100.1), read packet, TID: 0x0001, 0x3fcb5764.
D (44201) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_send_data: fd: 1
D (44211) mb_port.tcp.slave: 0x3fcb5c14, node: #1, socket(#56)[192.168.100.1], send packet TID: 0x0001:0x0001, 0x3fcb5764, len: 23,
D (44221) mb_port.tcp.slave: 0x3fcb5c14, node #1, socket(#56)(192.168.100.1), sent packet TID: 0x0001, 0x3fcb9774.
D (44231) mb_port.tcp.slave: Remove the message TID:0x0001
I (44241) SLAVE_TEST: OBJ 0x3fcb4224, HOLDING READ (44208515 us), ADDR:12, TYPE:2, INST_ADDR:0x3fc9f34c, SIZE:7

In the log fragment above I believe I see a transaction being received on socket 56 in the middle of transaction handling on socket 55. The socket 56 transaction affectively hijacks handling of the transaction from socket 55 which is never processed and enters limbo until next transaction is received. Upon that time the old transaction will be processed but the newly received on becomes stuck and so on... This can be seen in the following log fragment:

D (46901) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_recv_data: fd: 2
D (46901) mb_port.tcp.slave: 0x3fcb5c14, node #2, socket(#57) [192.168.100.1], receive data ready.
D (46911) mb_port.tcp.slave: 0x3fcb5c14, node #2, socket(#57)(192.168.100.1), received packet TID: 0x0001, frame: 0x3fcba96c, 12
D (46921) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x001e, start transaction.
D (46931) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), acknowledged packet TID: 0x001e.
D (46941) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_error: fd: 3
D (46951) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_error: fd: 1
D (46961) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_error: fd: 3
D (46961) mb_port.tcp.slave: 0x3fcb59d8, node #0, socket(#55)(192.168.100.1), read packet, TID: 0x001e, 0x3fcb5764.
D (46971) mb_port.tcp.slave: loop:0x3fcb5c14 mbs_on_send_data: fd: 0
D (46981) mb_port.tcp.slave: 0x3fcb5c14, node: #0, socket(#55)[192.168.100.1], send packet TID: 0x001e:0x001e, 0x3fcb5764, len: 23,
D (46991) mb_port.tcp.slave: 0x3fcb5c14, node #0, socket(#55)(192.168.100.1), sent packet TID: 0x001e, 0x3fcbb938.
D (47001) mb_port.tcp.slave: Remove the message TID:0x001e
I (47011) SLAVE_TEST: OBJ 0x3fcb4224, HOLDING READ (46978483 us), ADDR:12, TYPE:2, INST_ADDR:0x3fc9f34c, SIZE:7

I've checked the issue #140 and applied the fix mentioned there, this does not seem to help in this case, though the description is similar enough that maybe both observed behaviors may stem from the same underlying issue.

[alisitsyn]

Hi @blank-lgtm,

thank you for extended report of the issue. Could you please attach your sdkconfig file and full logs here? I will need to reproduce this once completed some other work. Thanks.

[blank-lgtm]

Hi @alisitsyn,

Thank you for the quick response. I'm attaching a folder with the entire log for the bug reproduction I've performed here (log.txt) along with a second log file with the default logging levels for the example from another run I've reproduced the bug in (log_verbose.txt).

The folder contains the used sdkconfig file (though I have removed the ssid and password for our company's wifi networks that were configured for the example).

I have also included a python script I've used to reproduce the bug, it is a simple modbus request client that allows for periodic polling of the device by a pre-configured request. I've reproduced the bug by letting one instance run and poll the device
py.exe .\modbus_stress_test.py <device IP>
while repeatedly and randomly starting another instance of the script with request count set to 1
py.exe .\modbus_stress_test.py <device IP> 1
eventually the continuously polling instance should experience timeouts.

Let me know if you need anything else.

esp_modbus_bug_report_resources.zip

[alisitsyn]

@blank-lgtm ,

Thank you for nicely created report. I will return to it once I have time for this. Sorry for possible inconvenience.
Thank you for patience.

[alisitsyn]

@blank-lgtm ,

Please see the fix for this issue in PR. If you can, please apply the changes from PR to you local esp-modbus stored in root/components folder of your project.
As per my results the PR fixes the issue and the slave gracefully closes the connection when receive the FIN packet.

I also checked the test sequence with the two instances of master using your script. It handles the disconnection correctly.

log.txt

The message E (18585) mb_port.tcp.slave: 0x3ffca238, node #1, socket(#56)(192.168.1.33), connection closed?, err= -11. means that the slave was receiving the FIN packet and closed the connection immediately.

I would appreciate if you can check the fix on your side with your environment.
Thanks.

[blank-lgtm]

@alisitsyn,

I've checked out 20f6021 and performed an additional sequence of tests on the tcp slave example. While I did observe an increase in the resiliency of the device during this round of testing it is still possible for the device to end in the previously described state, mostly in cases where I rapidly cycle through second modbus master instances.

I am attaching a log from one of the runs I performed today where the issue was induced by rapidly creating instance of the second modbus master just after it closed its connection. The transactions become mangled at around timestamp 25941.

modbus_instance_cycling_log.txt

The issue can also still appear during normal operation, though it feels like this has become less frequent with your changes. The mangling begins at timestamp 38341 in the following log.

modbus_sporadic_err_log.txt

[MD-Richards]

Hello,
I provided the following comment under issue #162, but after following study, I think my problem is more directly related to this issue. ...

I believe I'm having a problem related to this issue. I have merged the 7 files into my project, it did not solve the problem.
I have 2 Modbus TCP clients. Once client seems to be held up waiting for the other. If I disconnect one client, the other hangs. Here is the output of the serial monitor, I placed inline comments to narrate what is happening....
`Startup.......

rst:0x1 (POWERON_RESET),boot:0x12 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:6280
load:0x40078000,len:15864
load:0x40080400,len:3920
entry 0x4008063c
I (27) boot: ESP-IDF 5.5.3 2nd stage bootloader
I (27) boot: compile time Mar 23 2026 15:00:41
I (28) boot: Multicore bootloader
I (29) boot: chip revision: v3.1
I (31) boot.esp32: SPI Speed : 40MHz
I (35) boot.esp32: SPI Mode : DIO
I (39) boot.esp32: SPI Flash Size : 4MB
I (42) boot: Enabling RNG early entropy source...
I (47) boot: Partition Table:
I (49) boot: ## Label Usage Type ST Offset Length
I (56) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (62) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (69) boot: 2 factory factory app 00 00 00010000 00100000
I (75) boot: End of partition table
I (79) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=19dc4h (105924) map
I (122) esp_image: segment 1: paddr=00029dec vaddr=3ffb0000 size=02ce0h ( 11488) load
I (127) esp_image: segment 2: paddr=0002cad4 vaddr=40080000 size=03544h ( 13636) load
I (132) esp_image: segment 3: paddr=00030020 vaddr=400d0020 size=4a984h (305540) map
I (238) esp_image: segment 4: paddr=0007a9ac vaddr=40083544 size=0be8ch ( 48780) load
I (257) esp_image: segment 5: paddr=00086840 vaddr=50000000 size=00020h ( 32) load
I (265) boot: Loaded app from partition at offset 0x10000
I (265) boot: Disabling RNG early entropy source...
I (278) cpu_start: Multicore app
I (286) cpu_start: GPIO 3 and 1 are used as console UART I/O pins
I (286) cpu_start: Pro cpu start user code
I (286) cpu_start: cpu freq: 160000000 Hz
I (288) app_init: Application information:
I (292) app_init: Project name: modbus_tcp_slave
I (297) app_init: App version: 1
I (300) app_init: Compile time: Mar 23 2026 15:00:06
I (305) app_init: ELF file SHA256: 4e2e26b5d...
I (309) app_init: ESP-IDF: 5.5.3
I (313) efuse_init: Min chip rev: v0.0
I (317) efuse_init: Max chip rev: v3.99
I (321) efuse_init: Chip rev: v3.1
I (325) heap_init: Initializing. RAM available for dynamic allocation:
I (331) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (336) heap_init: At 3FFB4ED8 len 0002B128 (172 KiB): DRAM
I (341) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (347) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (352) heap_init: At 4008F3D0 len 00010C30 (67 KiB): IRAM
I (359) spi_flash: detected chip: generic
I (361) spi_flash: flash io: dio
I (365) main_task: Started on CPU0
I (375) main_task: Calling app_main()
I (465) esp_eth.netif.netif_glue: d4:8c:49:a6:af:23
I (465) esp_eth.netif.netif_glue: ethernet attached to netif
I (2565) ethernet_connect: Waiting for IP(s).
I (3565) esp_netif_handlers: example_netif_eth ip: 192.168.1.220, mask: 255.255.255.0, gw: 192.168.1.1
I (3565) ethernet_connect: Got IPv4 event: Interface "example_netif_eth" address: 192.168.1.220
I (3565) example_common: Connected to example_netif_eth
I (3575) example_common: - IPv4 address: 192.168.1.220,
I (3795) mdns_mem: mDNS task will be created from internal RAM
I (3795) port.utils: hostname set to: [mb_slave_tcp_a6af23]
I (3795) port.utils: mdns delegate hostname set to: [mb_slave_tcp_01]
I (3795) port.utils: IP: 192.168.1.220
I (3805) port.utils: GW: 192.168.1.1
I (3805) port.utils: NETMASK: 255.255.255.0
D (3815) mb_object.slave: created object mbs_tcp@0x3ffbe404
I (3815) port.utils: Socket (#54), listener on port: 1502, errno=0
I (3825) mb_port.tcp.slave: loop:0x3ffbfe88 mbs_on_ready: fd: -1, bind is done
D (3825) mb_object.slave: 0x3ffbe404:EV_READY
D (3835) mb_object.slave: 0x3ffbe404:EV_READY
I (3835) MB_TCP_SLAVE: Slave TCP started (app_main)
I (3845) MB_TCP_SLAVE: Slave TCP is started
I (3845) MB_TCP_SLAVE: Start Modbus server...

HMI connects here (192.168.1.86 polling 2 input registers at approx. 1,000ms...)

I (4235) port.utils: Socket (#55), accept client connection from address[port]: 192.168.1.86[52071]
D (4825) mb_object.slave: 0x3ffbe404:EV_READY
D (5245) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (5245) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (5245) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (5245) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (5255) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (5255) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (5265) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 15999
I (5265) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (6315) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (6315) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (6315) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (6325) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (6325) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (6335) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (6335) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16050
I (6345) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (7355) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (7355) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (7355) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (7365) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (7365) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (7375) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (7375) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16027
I (7385) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (8425) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (8425) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (8425) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (8435) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (8435) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (8435) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (8445) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 15959
I (8445) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (9455) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (9455) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (9455) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (9465) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (9465) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (9475) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (9475) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16007
I (9485) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2

2nd client connects here (PC 192.168.1.120 running Mosbus Poll software - polling 2 holding registers at approx. 80ms)
Note that we now have alternating HOLDING READS and INPUT READS (more HOLDING READS based on the different polling rate).
At this point, the client reading the HOLDING registers experiences regular timeouts, presumably waiting for the other slower client to read.

I (10215) port.utils: Socket (#56), accept client connection from address[port]: 192.168.1.120[59633]
D (10265) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (10265) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (10265) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (10275) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (10275) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (10285) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (10285) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16374
I (10295) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (10365) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (10365) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (10365) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (10375) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (10375) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (10385) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (10385) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16394
I (10395) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (10465) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (10465) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (10465) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (10475) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (10475) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (10485) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (10485) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16330
I (10495) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (10565) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (10565) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (10565) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (10575) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (10575) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (10585) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (10585) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16378
I (10595) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (11515) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (11515) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (11515) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
W (11525) mb_port.tcp.slave: 0x3ffbfe88, node #1, socket(#56), handling time [ms]: 957, exceeds slave response time in master.
D (11535) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (11535) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (11545) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (11545) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 28763
I (11555) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (11615) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (11615) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (11615) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (11625) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (11625) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (11635) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (11635) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16387
I (11645) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (11715) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (11715) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (11715) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (11725) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (11725) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (11735) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (11735) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16326
I (11745) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (12665) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (12665) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (12665) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
W (12675) mb_port.tcp.slave: 0x3ffbfe88, node #1, socket(#56), handling time [ms]: 957, exceeds slave response time in master.
D (12685) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (12685) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (12695) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (12695) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 28772
I (12705) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (12775) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (12775) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (12775) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (12785) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (12785) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (12795) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (12795) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16398
I (12805) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (12875) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (12875) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (12875) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (12885) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (12885) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (12895) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (12895) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16315
I (12905) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (13825) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (13825) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (13825) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
W (13825) mb_port.tcp.slave: 0x3ffbfe88, node #1, socket(#56), handling time [ms]: 953, exceeds slave response time in master.
D (13835) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (13845) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (13845) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (13855) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 28772
I (13865) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (13925) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (13925) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (13925) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (13935) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (13935) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (13945) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (13945) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16445
I (13955) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (14025) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (14025) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (14025) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (14035) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (14035) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (14045) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (14045) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16335
I (14055) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (14975) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (14975) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (14975) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
W (14975) mb_port.tcp.slave: 0x3ffbfe88, node #1, socket(#56), handling time [ms]: 954, exceeds slave response time in master.
D (14985) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (14995) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (15005) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (15005) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 28791
I (15015) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (15075) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (15075) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (15075) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (15085) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (15085) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (15095) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (15095) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16972
I (15105) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (15175) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (15175) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (15175) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (15185) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (15185) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (15195) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (15195) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16307
I (15205) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (16125) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (16125) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (16125) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
W (16125) mb_port.tcp.slave: 0x3ffbfe88, node #1, socket(#56), handling time [ms]: 955, exceeds slave response time in master.
D (16145) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (16145) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (16155) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (16155) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 28759
I (16165) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (16225) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (16225) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (16225) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (16235) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (16235) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (16245) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (16245) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16406
I (16255) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (16325) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (16325) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (16325) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (16335) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (16335) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (16345) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (16345) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16311
I (16355) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (17275) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (17275) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (17275) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
W (17275) mb_port.tcp.slave: 0x3ffbfe88, node #1, socket(#56), handling time [ms]: 956, exceeds slave response time in master.
D (17295) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (17295) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (17305) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (17305) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 28771
I (17315) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (17395) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (17395) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (17395) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (17405) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (17405) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (17415) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (17415) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16390
I (17425) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (17495) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (17495) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (17495) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (17505) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (17505) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (17515) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (17515) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16331
I (17525) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (18445) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (18445) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (18445) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
W (18455) mb_port.tcp.slave: 0x3ffbfe88, node #1, socket(#56), handling time [ms]: 957, exceeds slave response time in master.
D (18465) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (18465) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (18475) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (18475) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 28815
I (18485) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (18545) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (18545) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (18545) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (18555) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (18555) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (18565) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (18565) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16394
I (18575) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (18645) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (18645) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (18645) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (18655) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (18655) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (18665) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (18665) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16323
I (18675) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (19745) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (19745) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (19745) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (19755) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (19755) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (19765) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (19765) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16370
I (19775) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2

2nd client disconnect here (PC 192.168.1.120)
from here on, there are only INPUT READS in the output, but this is wrong, as the 1st HMI client still online is requesting HOLDING READS.
1st client is now stuck in permanent response timeout and no longer is able to make any sucsessful reads.

E (20145) mb_port.tcp.slave: 0x3ffbfc44, node #1, socket(#56), communication fail, err= -11
I (20715) port.utils: Socket (#56), accept client connection from address[port]: 192.168.1.86[52083]
D (22715) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (22715) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (22715) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (22725) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (22725) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (22735) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (22735) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16390
I (22745) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
E (22965) mb_port.tcp.slave: 0x3ffbfc44, node #0, socket(#55), communication fail, err= -11
I (23705) port.utils: Socket (#55), accept client connection from address[port]: 192.168.1.86[52086]
D (25705) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (25705) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (25705) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (25715) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (25715) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (25725) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (25725) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16608
I (25735) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
E (25955) mb_port.tcp.slave: 0x3ffbfc44, node #1, socket(#56), communication fail, err= -11
I (26705) port.utils: Socket (#56), accept client connection from address[port]: 192.168.1.86[52088]
D (28705) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (28705) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (28705) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (28715) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (28715) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (28725) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (28725) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16422
I (28735) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
E (28955) mb_port.tcp.slave: 0x3ffbfc44, node #0, socket(#55), communication fail, err= -11
I (29705) port.utils: Socket (#55), accept client connection from address[port]: 192.168.1.86[52091]
D (31735) mb_object.slave: 0x3ffbe404: Unexpected event 0x40 or timeout?
D (31755) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (31755) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (31755) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (31765) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (31765) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (31775) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (31775) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 16291

I (2100715) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
E (2100935) mb_port.tcp.slave: 0x3ffbfc44, node #1, socket(#56), communication fail, err= -11
I (2101685) port.utils: Socket (#56), accept client connection from address[port]: 192.168.1.86[53932]
D (2103685) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2103685) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2103685) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (2103695) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2103695) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2103705) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2103705) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 17277
I (2103715) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
E (2103935) mb_port.tcp.slave: 0x3ffbfc44, node #0, socket(#55), communication fail, err= -11
I (2104685) port.utils: Socket (#55), accept client connection from address[port]: 192.168.1.86[53935]
I (2105485) port.utils: Socket (#57), accept client connection from address[port]: 192.168.1.120[61943]
D (2105535) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2105535) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2105535) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (2105545) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2105545) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2105555) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2105555) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 17209
I (2105565) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
E (2105835) mb_port.tcp.slave: 0x3ffbfc44, node #1, socket(#56), communication fail, err= -11
D (2106505) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2106505) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2106505) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.

Reconnected 2nd client at 192.168.1.120 here.....
1st client comes back on line and every thing returns to normal, except still getting the regular timeouts from the second client.

W (2106505) mb_port.tcp.slave: 0x3ffbfe88, node #2, socket(#57), handling time [ms]: 974, exceeds slave response time in master.
D (2106525) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2106525) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2106535) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2106535) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 29839
I (2106545) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (2106685) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2106685) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2106685) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (2106695) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2106695) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2106705) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2106705) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 17265
I (2106715) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (2106785) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2106785) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2106785) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (2106795) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2106795) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2106805) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2106805) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 17225
I (2106815) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (2107745) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2107745) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2107745) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
W (2107755) mb_port.tcp.slave: 0x3ffbfe88, node #2, socket(#57), handling time [ms]: 967, exceeds slave response time in master.
D (2107765) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2107765) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2107775) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2107775) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 29816
I (2107785) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (2107845) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2107845) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2107845) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (2107855) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2107855) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2107865) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2107865) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 18245
I (2107875) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (2107945) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2107945) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2107945) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (2107955) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2107955) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2107965) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2107965) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 17189
I (2107975) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (2108895) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2108895) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2108895) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
W (2108905) mb_port.tcp.slave: 0x3ffbfe88, node #2, socket(#57), handling time [ms]: 957, exceeds slave response time in master.
D (2108915) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2108915) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2108925) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2108925) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 29819
I (2108935) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (2109005) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2109005) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2109005) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (2109015) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2109025) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2109025) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2109035) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 18412
I (2109035) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (2109105) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2109105) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2109105) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (2109115) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2109115) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2109125) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2109125) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 17229
I (2109135) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (2110045) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2110045) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2110045) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
W (2110055) mb_port.tcp.slave: 0x3ffbfe88, node #2, socket(#57), handling time [ms]: 950, exceeds slave response time in master.
D (2110065) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2110075) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2110075) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2110085) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 29828
I (2110085) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (2110155) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2110155) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2110155) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (2110165) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2110175) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2110175) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2110185) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 17269
I (2110185) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (2110255) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2110255) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2110255) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (2110265) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2110265) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2110275) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2110275) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 17225
I (2110285) MB_TCP_SLAVE: INPUT READ: offset=0 type=8 size=2
D (2111215) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2111215) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2111215) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
W (2111225) mb_port.tcp.slave: 0x3ffbfe88, node #2, socket(#57), handling time [ms]: 971, exceeds slave response time in master.
D (2111235) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2111245) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2111245) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2111255) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 29824
I (2111255) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (2111315) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2111325) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2111325) mb_object.slave: 0x3ffbe404: function (0x3), invoke handler 0x400d5874.
D (2111325) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2111335) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2111335) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2111345) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 17269
I (2111345) MB_TCP_SLAVE: HOLDING READ: offset=4 type=2 size=2
D (2111415) mb_object.slave: 0x3ffbe404:EV_FRAME_RECEIVED
D (2111415) mb_object.slave: 0x3ffbe404:EV_EXECUTE
D (2111415) mb_object.slave: 0x3ffbe404: function (0x4), invoke handler 0x400d59e0.
D (2111425) mb_object.slave: 0x3ffbe404:EV_MASTER_FRAME_SENT
D (2111425) mb_object.slave: 0x3ffbe404, set event EV_ERROR_OK
D (2111435) mb_object.slave: 0x3ffbe404:EV_ERROR_PROCESS
D (2111435) mb_object.slave: 0x3ffbe404, transaction processing time(us) = 17190
`

Thank you.

[alisitsyn]

@MD-Richards, @blank-lgtm,

I can reproduce the issue with disconnected client and keep alive loop. This looks like stack - network related issue. I will update you once the reliable solution found and ready to check.

[alisitsyn]

@MD-Richards, @blank-lgtm,

The issue has been fixed here.
Handling logic of slave mbs_on_error mbs_on_send_data event handlers is updated.
Now after client disconnection the slave can safely proceed with other opened client connections with no delays.
Please take a look and help to test.
Thank you.

[blank-lgtm]

Hi @alisitsyn,

I've re-tested the slave example with bugfix/fix_slave_error_disconnected_node checked out. While I can sometimes see the latency on the polling master instance spike up to roughly 1100 ms when the device is processing requests from both the polling and single-request masters, the device no longer hangs the polling connection once the request from the second master instance is processed.

As far as I'm concerned, this issue is resolved now.