search

slowtec / tokio-modbus

A tokio-based modbus library
Apache License 2.0
398 stars 120 forks source link

Poor recovery from malformed frames in RTU #60

Open MightyPork opened 4 years ago

MightyPork commented 4 years ago

We have a modbus slave which implements modbus in the usual vendor way, i.e., wrong: It does not send CRC with error frames.

Req: 0A 01 04 A1 00 01 AC 63
Resp: 0A 81 02 <no_crc>

To debug this, I copied the crate to a local folder and added trace logging to the RTU decoder.

Trace logs (long) ``` [2020-05-19T11:37:31.393Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x01") [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x01") [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] --- decode b"\x01" [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x01" [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] pdu len none [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] PDU len is None [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:31.393Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x01\x83") [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x01\x83") [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] --- decode b"\x01\x83" [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x01\x83" [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] len=Some(2) [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] PDU len is Some(2) [2020-05-19T11:37:31.393Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x01\x83", len 2) [2020-05-19T11:37:31.394Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:31.394Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:31.394Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:31.394Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:31.395Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:31.395Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x01\x83\x02") [2020-05-19T11:37:31.395Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x01\x83\x02") [2020-05-19T11:37:31.395Z TRACE tokio_modbus::codec::rtu] --- decode b"\x01\x83\x02" [2020-05-19T11:37:31.395Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x01\x83\x02" [2020-05-19T11:37:31.395Z TRACE tokio_modbus::codec::rtu] len=Some(2) [2020-05-19T11:37:31.395Z TRACE tokio_modbus::codec::rtu] PDU len is Some(2) [2020-05-19T11:37:31.395Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x01\x83\x02", len 2) [2020-05-19T11:37:31.395Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:31.395Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:31.395Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:31.395Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:31.878Z ERROR fb_modbus::client] Read error: Timed out [2020-05-19T11:37:31.878Z DEBUG fb_modbus::client] Retrying (retry 1/3) [2020-05-19T11:37:32.878Z TRACE tokio_modbus::codec::rtu] encode RequestAdu { hdr: Header { slave_id: 1 }, pdu: RequestPdu(ReadHoldingRegisters(1, 3)), disconnect: false } [2020-05-19T11:37:32.879Z TRACE tokio_modbus::codec::rtu] encoded as b"\x01\x03\0\x01\0\x03T\x0b" [2020-05-19T11:37:32.879Z TRACE tokio_util::codec::framed_write] flushing framed transport [2020-05-19T11:37:32.879Z TRACE tokio_util::codec::framed_write] writing; remaining=8 [2020-05-19T11:37:32.879Z TRACE tokio_util::codec::framed_write] framed transport flushed [2020-05-19T11:37:32.895Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:32.895Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x01\x83\x02\x01") [2020-05-19T11:37:32.895Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x01\x83\x02\x01") [2020-05-19T11:37:32.895Z TRACE tokio_modbus::codec::rtu] --- decode b"\x01\x83\x02\x01" [2020-05-19T11:37:32.895Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x01\x83\x02\x01" [2020-05-19T11:37:32.895Z TRACE tokio_modbus::codec::rtu] len=Some(2) [2020-05-19T11:37:32.895Z TRACE tokio_modbus::codec::rtu] PDU len is Some(2) [2020-05-19T11:37:32.895Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x01\x83\x02\x01", len 2) [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:32.896Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x01\x83\x02\x01\x83") [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x01\x83\x02\x01\x83") [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] --- decode b"\x01\x83\x02\x01\x83" [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x01\x83\x02\x01\x83" [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] len=Some(2) [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] PDU len is Some(2) [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x01\x83\x02\x01\x83", len 2) [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] good length for a packet: b"\x01\x83\x02\x01\x83" [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] adu b"\x01\x83\x02" [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] crc b"\x01\x83" [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] crc error, adu [1, 131, 2], expected 0x183 [2020-05-19T11:37:32.896Z TRACE tokio_modbus::codec::rtu] err Custom { kind: InvalidData, error: "Invalid CRC: expected = 0x0183, actual = 0xC0F1" }, restore input buffer [2020-05-19T11:37:32.896Z WARN tokio_modbus::codec::rtu] Failed to decode response frame: Invalid CRC: expected = 0x0183, actual = 0xC0F1 [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] recover_on_error [2020-05-19T11:37:32.897Z DEBUG tokio_modbus::codec::rtu] Dropped first byte: 1 [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] decoder loop retry [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x83\x02\x01\x83" [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] len=Some(3) [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] PDU len is Some(3) [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x83\x02\x01\x83", len 3) [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:32.897Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x83\x02\x01\x83\x02") [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x83\x02\x01\x83\x02") [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] --- decode b"\x83\x02\x01\x83\x02" [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x83\x02\x01\x83\x02" [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] len=Some(3) [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] PDU len is Some(3) [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x83\x02\x01\x83\x02", len 3) [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:32.897Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:32.898Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:33.380Z ERROR fb_modbus::client] Read error: Timed out [2020-05-19T11:37:33.380Z DEBUG fb_modbus::client] Retrying (retry 2/3) [2020-05-19T11:37:34.381Z TRACE tokio_modbus::codec::rtu] encode RequestAdu { hdr: Header { slave_id: 1 }, pdu: RequestPdu(ReadHoldingRegisters(1, 3)), disconnect: false } [2020-05-19T11:37:34.381Z TRACE tokio_modbus::codec::rtu] encoded as b"\x01\x03\0\x01\0\x03T\x0b" [2020-05-19T11:37:34.381Z TRACE tokio_util::codec::framed_write] flushing framed transport [2020-05-19T11:37:34.381Z TRACE tokio_util::codec::framed_write] writing; remaining=8 [2020-05-19T11:37:34.381Z TRACE tokio_util::codec::framed_write] framed transport flushed [2020-05-19T11:37:34.398Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] --- decode b"\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] len=Some(3) [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] PDU len is Some(3) [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x83\x02\x01\x83\x02\x01", len 3) [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] good length for a packet: b"\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] adu b"\x83\x02\x01\x83" [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] crc b"\x02\x01" [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] crc error, adu [131, 2, 1, 131], expected 0x201 [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] err Custom { kind: InvalidData, error: "Invalid CRC: expected = 0x0201, actual = 0xC851" }, restore input buffer [2020-05-19T11:37:34.398Z WARN tokio_modbus::codec::rtu] Failed to decode response frame: Invalid CRC: expected = 0x0201, actual = 0xC851 [2020-05-19T11:37:34.398Z TRACE tokio_modbus::codec::rtu] recover_on_error [2020-05-19T11:37:34.398Z DEBUG tokio_modbus::codec::rtu] Dropped first byte: 83 [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] decoder loop retry [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01" [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01", len 133) [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:34.399Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83", len 133) [2020-05-19T11:37:34.399Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:34.400Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02", len 133) [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:34.400Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:34.882Z ERROR fb_modbus::client] Read error: Timed out [2020-05-19T11:37:34.882Z DEBUG fb_modbus::client] Retrying (retry 3/3) [2020-05-19T11:37:35.882Z TRACE tokio_modbus::codec::rtu] encode RequestAdu { hdr: Header { slave_id: 1 }, pdu: RequestPdu(ReadHoldingRegisters(1, 3)), disconnect: false } [2020-05-19T11:37:35.883Z TRACE tokio_modbus::codec::rtu] encoded as b"\x01\x03\0\x01\0\x03T\x0b" [2020-05-19T11:37:35.883Z TRACE tokio_util::codec::framed_write] flushing framed transport [2020-05-19T11:37:35.883Z TRACE tokio_util::codec::framed_write] writing; remaining=8 [2020-05-19T11:37:35.883Z TRACE tokio_util::codec::framed_write] framed transport flushed [2020-05-19T11:37:35.900Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:35.900Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:35.900Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:35.901Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:35.901Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:35.901Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:35.901Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:35.901Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01", len 133) [2020-05-19T11:37:35.901Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:35.901Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:35.901Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:35.901Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:35.901Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:35.901Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:35.901Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:35.902Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:35.902Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:35.902Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:35.902Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:35.902Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83", len 133) [2020-05-19T11:37:35.902Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:35.902Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:35.902Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:35.902Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:35.902Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:35.902Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:35.902Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:35.903Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:35.903Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:35.903Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:35.903Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:35.903Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02", len 133) [2020-05-19T11:37:35.903Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:35.903Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:35.903Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:35.903Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:36.385Z ERROR fb_modbus::client] Read error: Timed out [2020-05-19T11:37:36.385Z WARN fb_modbus::client] Retries exhausted! [2020-05-19T11:37:36.385Z ERROR mod_inepro380max] Error reading amps mb ID 1: Timed out [2020-05-19T11:37:36.886Z TRACE tokio_modbus::codec::rtu] encode RequestAdu { hdr: Header { slave_id: 1 }, pdu: RequestPdu(ReadHoldingRegisters(1, 3)), disconnect: false } [2020-05-19T11:37:36.886Z TRACE tokio_modbus::codec::rtu] encoded as b"\x01\x03\0\x01\0\x03T\x0b" [2020-05-19T11:37:36.886Z TRACE tokio_util::codec::framed_write] flushing framed transport [2020-05-19T11:37:36.886Z TRACE tokio_util::codec::framed_write] writing; remaining=8 [2020-05-19T11:37:36.886Z TRACE tokio_util::codec::framed_write] framed transport flushed [2020-05-19T11:37:36.902Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:36.902Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:36.902Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:36.902Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:36.902Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:36.902Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:36.902Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:36.902Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01", len 133) [2020-05-19T11:37:36.902Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:36.902Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:36.902Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:36.902Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:36.903Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:36.903Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:36.903Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:36.903Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:36.903Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:36.903Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:36.903Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:36.903Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83", len 133) [2020-05-19T11:37:36.903Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:36.903Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:36.903Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:36.903Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:36.904Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:36.904Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:36.904Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:36.904Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:36.904Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:36.904Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:36.904Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:36.904Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02", len 133) [2020-05-19T11:37:36.904Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:36.904Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:36.904Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:36.904Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:37.388Z ERROR fb_modbus::client] Read error: Timed out [2020-05-19T11:37:37.388Z DEBUG fb_modbus::client] Retrying (retry 1/3) [2020-05-19T11:37:38.388Z TRACE tokio_modbus::codec::rtu] encode RequestAdu { hdr: Header { slave_id: 1 }, pdu: RequestPdu(ReadHoldingRegisters(1, 3)), disconnect: false } [2020-05-19T11:37:38.388Z TRACE tokio_modbus::codec::rtu] encoded as b"\x01\x03\0\x01\0\x03T\x0b" [2020-05-19T11:37:38.389Z TRACE tokio_util::codec::framed_write] flushing framed transport [2020-05-19T11:37:38.389Z TRACE tokio_util::codec::framed_write] writing; remaining=8 [2020-05-19T11:37:38.389Z TRACE tokio_util::codec::framed_write] framed transport flushed [2020-05-19T11:37:38.405Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:38.405Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:38.405Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:38.405Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:38.405Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:38.405Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:38.405Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:38.405Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01", len 133) [2020-05-19T11:37:38.405Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:38.405Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:38.405Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:38.405Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:38.405Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83", len 133) [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:38.406Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:38.406Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:38.407Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:38.407Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:38.407Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:38.407Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:38.407Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02", len 133) [2020-05-19T11:37:38.407Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:38.407Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:38.407Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:38.407Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:38.891Z ERROR fb_modbus::client] Read error: Timed out [2020-05-19T11:37:38.891Z DEBUG fb_modbus::client] Retrying (retry 2/3) [2020-05-19T11:37:39.891Z TRACE tokio_modbus::codec::rtu] encode RequestAdu { hdr: Header { slave_id: 1 }, pdu: RequestPdu(ReadHoldingRegisters(1, 3)), disconnect: false } [2020-05-19T11:37:39.891Z TRACE tokio_modbus::codec::rtu] encoded as b"\x01\x03\0\x01\0\x03T\x0b" [2020-05-19T11:37:39.891Z TRACE tokio_util::codec::framed_write] flushing framed transport [2020-05-19T11:37:39.891Z TRACE tokio_util::codec::framed_write] writing; remaining=8 [2020-05-19T11:37:39.891Z TRACE tokio_util::codec::framed_write] framed transport flushed [2020-05-19T11:37:39.907Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:39.907Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:39.907Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:39.907Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:39.907Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:39.907Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:39.907Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:39.907Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01", len 133) [2020-05-19T11:37:39.907Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:39.907Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:39.907Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:39.907Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:39.908Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83", len 133) [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:39.908Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:39.908Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:39.909Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:39.909Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:39.909Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:39.909Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:39.909Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02", len 133) [2020-05-19T11:37:39.909Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:39.909Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:39.909Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:39.909Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:40.392Z ERROR fb_modbus::client] Read error: Timed out [2020-05-19T11:37:40.393Z DEBUG fb_modbus::client] Retrying (retry 3/3) [2020-05-19T11:37:41.393Z TRACE tokio_modbus::codec::rtu] encode RequestAdu { hdr: Header { slave_id: 1 }, pdu: RequestPdu(ReadHoldingRegisters(1, 3)), disconnect: false } [2020-05-19T11:37:41.393Z TRACE tokio_modbus::codec::rtu] encoded as b"\x01\x03\0\x01\0\x03T\x0b" [2020-05-19T11:37:41.393Z TRACE tokio_util::codec::framed_write] flushing framed transport [2020-05-19T11:37:41.393Z TRACE tokio_util::codec::framed_write] writing; remaining=8 [2020-05-19T11:37:41.393Z TRACE tokio_util::codec::framed_write] framed transport flushed [2020-05-19T11:37:41.409Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:41.409Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01") [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01" [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01", len 133) [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:41.410Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:41.410Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83") [2020-05-19T11:37:41.411Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:41.411Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83" [2020-05-19T11:37:41.411Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:41.411Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:41.411Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83", len 133) [2020-05-19T11:37:41.411Z TRACE tokio_modbus::codec::rtu] Incomplete frame [2020-05-19T11:37:41.411Z TRACE tokio_modbus::codec::rtu] no retry [2020-05-19T11:37:41.411Z TRACE tokio_modbus::codec::rtu] decode resulted in -> None [2020-05-19T11:37:41.411Z TRACE tokio_modbus::codec::rtu] frame is partial, ask for more bytes [2020-05-19T11:37:41.411Z TRACE tokio_util::codec::framed_read] attempting to decode a frame [2020-05-19T11:37:41.411Z TRACE tokio_modbus::codec::rtu] ClientCodec::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:41.411Z TRACE tokio_modbus::codec::rtu] ResponseDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02") [2020-05-19T11:37:41.412Z TRACE tokio_modbus::codec::rtu] --- decode b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:41.412Z TRACE tokio_modbus::codec::rtu] get_response_pdu_len b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02" [2020-05-19T11:37:41.412Z TRACE tokio_modbus::codec::rtu] len=Some(133) [2020-05-19T11:37:41.412Z TRACE tokio_modbus::codec::rtu] PDU len is Some(133) [2020-05-19T11:37:41.412Z TRACE tokio_modbus::codec::rtu] FrameDecoder::decode(b"\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02\x01\x83\x02", len 133) (it continues..) ``` (without the trace logging, you really can't see anything, the parser continuously fails.)

Several things are going wrong:

All (possibly valid) responses received while the decoder is set on collecting the 133 bytes, will be lost. I'll admit I don't know how to fix it or work around the problem :/

MightyPork commented 4 years ago

I have a solution of sorts, maybe I'll make a PR later if it proves reliable.

fn clear_framed_read_buffer<T, U>(framed_mut : &mut Framed<T, U>) {
    let framed = unsafe { std::ptr::read(framed_mut) };

    let mut parts = framed.into_parts();
    parts.read_buf.clear();

    unsafe {
        std::ptr::write(framed_mut, Framed::from_parts(parts));
    }
}

This is called in Context::call (service::*) before the .send(), like this:

    async fn call(&mut self, req: Request) -> Result<Response, Error> {
        let disconnect = req == Request::Disconnect;
        let req_adu = self.next_request_adu(req, disconnect);
        let req_hdr = req_adu.hdr;

        super::clear_framed_read_buffer(&mut self.service); // <---- here

        self.service.send(req_adu).await?;
        let res_adu = self.service.next().await.unwrap()?;

        match res_adu.pdu {
            ResponsePdu(Ok(res)) => verify_response_header(req_hdr, res_adu.hdr).and(Ok(res)),
            ResponsePdu(Err(err)) => Err(Error::new(ErrorKind::Other, err)),
        }
    }
fastfailure commented 2 years ago

Any news on this subject? I've encountered this situation too. Sadly I think I'm not experienced enough to try to come up with a fix myself

MightyPork commented 2 years ago

I'm still using the hack shown in the previous post, it's quite reliable but you of course need to copy the library to your project and add the patch locally. I don't see any change addressing this in the upstream code sadly

uklotzde commented 2 years ago

Pull requests are welcome!

Unfortunately, we (the maintainers) cannot offer software development or consulting services for free.

fastfailure commented 2 years ago

Thanks for the feedback, this is fine, I will use what is available and in time I will try to understand the codebase.

fastfailure commented 1 year ago

I ended up wrapping each modbus read with tokio::select!, pairing it with a simple timer. If the timer finishes before the read it (and therefore the select!) returns an error.

A raw example:

use std::time::Duration;
use thiserror::Error;
use tokio_modbus::client::Context;
use tokio_modbus::prelude::*;
use tracing::{debug, error, trace};

#[derive(Debug, Error)]
#[error("timeout is expired for {scope}")]
pub struct TimeoutExpired {
    scope: String,
    timeout: Duration,
}

/// Timer to be `tokio::select`ed against any Modbus call, to act as watchdog.
pub async fn dead_men_timer(scope: String, timeout: Duration) -> Result<(), TimeoutExpired> {
    trace!("Timer started for: {}.", scope);
    tokio::time::sleep(timeout).await;
    debug!("{}: timeout expired.", scope);
    Err(TimeoutExpired { scope, timeout })
}

async fn read_with_timeout(
    ctx: &mut Context,
    addr_start: u16,
    addr_amount: u16,
    modbus_read_timeout: Duration,
) -> Result<Vec<u16>, TimeoutExpired> {
    tokio::select!(
        r = ctx.read_holding_registers(addr_start, addr_amount) => {
            Ok(r.unwrap())
        },
        Err(e) = dead_men_timer(format!("example Modbus read"), modbus_read_timeout) => {
            // dead_men_timer() never returns Ok
            error!("Failed reading: {:?}", e);
            Err(e)
        }
    )
}

I hope this can be useful to someone.

ColinFinck commented 1 year ago

@lanquil I'm using a similar timeout when connecting to or reading from a Modbus device. However, I'm using tokio::time::timeout, which achieves the same as your code, but is provided by Tokio itself.

Having tried multiple Rust crates for Modbus and other industrial protocols, I have hardly found one that supports timeouts for every operation or properly recovers from faults under all circumstances. This is why I'm now following a simple strategy for all such crates:

  1. Put a tokio::time::timeout around every crate call that communicates with the target device. Use a generous timeout (like 10 seconds) to not kill any legitimately late response.
  2. If an error or timeout is returned by a crate call, consider the client session poisoned, drop it, and recreate it from scratch.

This is basic and some may consider it just a workaround. But doing it like that scales much better than relying on every crate to care about timeouts or provide perfect recovery. I have stopped expecting these features from external crates, when I can provide them myself as a crate user.

gustavowd commented 1 year ago

Hi. I am having this problem as well. However, after some timeouts i'm getting this erros:

kind: InvalidData, error: "Too many retries" Kind(BrokenPipe)

And after the broken pipe, the recovery by timeout does not work anymore. I was able to clear the buffer without using unsafe code. I'll try the code that clears the buffer before send a new RTU message. If it works, i will make a pull request later.

gustavowd commented 1 year ago

Actually before https://github.com/slowtec/tokio-modbus/commit/f9782f7122da3e6ff6078fdf41d452441d9a73f8 I only got timeout errors and was always able to recover communication. After this commit I always get these broken pipe errors with no recovery.

MightyPork commented 1 year ago

I'm trying to upgrade from 0.4 today, all the tokio changes were a bit difficult, but this issue got simpler:

my previous workaround no longer needs unsafe and can be reduced to:

self.framed.read_buffer_mut().clear();