Hermes duplicates SendPacket events emitted by EndBlock

[michaelfig]

Crate

ibc-rs (Hermes)

Summary of Bug

EndBlock SendPacket events appear to be unexpectedly duplicated, causing an error with a reused sequence number when trying to send the batch.

Version

#1840 merged with #1801

Steps to Reproduce

Send a single packet from EndBlock on an established channel.

Here is the relevant logs after sending a single packet from EndBlock:

�[36mhermes_1  |�[0m 2022-02-04T18:54:24.474917Z TRACE ThreadId(56) packet_cmd{src_chain=agoric src_port=port-4 src_channel=channel-0 dst_chain=cosmoshub-testnet}: handling command IbcEvents { batch: EventBatch { chain_id: ChainId { id: "agoric", version: 0 }, height: Height { revision: 0, height: 978 }, events: [SendPacket(SendPacket { height: Height { revision: 0, height: 978 }, packet: Packet { sequence: Sequence(1), source_port: PortId("port-4"), source_channel: ChannelId("channel-0"), destination_port: PortId("transfer"), destination_channel: ChannelId("channel-118"), data: [123, 34, 97, 109, 111, 117, 110, 116, 34, 58, 34, 49, 48, 48, 34, 44, 34, 100, 101, 110, 111, 109, 34, 58, 34, 102, 97, 107, 101, 116, 111, 107, 101, 110, 34, 44, 34, 114, 101, 99, 101, 105, 118, 101, 114, 34, 58, 34, 99, 111, 115, 109, 111, 115, 49, 100, 108, 117, 97, 53, 115, 50, 55, 109, 106, 118, 116, 48, 116, 101, 100, 108, 102, 113, 48, 51, 109, 51, 114, 99, 51, 48, 97, 115, 118, 116, 53, 119, 120, 116, 53, 115, 56, 34, 125], timeout_height: Height { revision: 0, height: 0 }, timeout_timestamp: Timestamp { time: Some(Time(PrimitiveDateTime { date: Date { year: 2022, ordinal: 35 }, time: Time { hour: 19, minute: 4, second: 13, nanosecond: 872918905 } })) } } }), SendPacket(SendPacket { height: Height { revision: 0, height: 978 }, packet: Packet { sequence: Sequence(1), source_port: PortId("port-4"), source_channel: ChannelId("channel-0"), destination_port: PortId("transfer"), destination_channel: ChannelId("channel-118"), data: [123, 34, 97, 109, 111, 117, 110, 116, 34, 58, 34, 49, 48, 48, 34, 44, 34, 100, 101, 110, 111, 109, 34, 58, 34, 102, 97, 107, 101, 116, 111, 107, 101, 110, 34, 44, 34, 114, 101, 99, 101, 105, 118, 101, 114, 34, 58, 34, 99, 111, 115, 109, 111, 115, 49, 100, 108, 117, 97, 53, 115, 50, 55, 109, 106, 118, 116, 48, 116, 101, 100, 108, 102, 113, 48, 51, 109, 51, 114, 99, 51, 48, 97, 115, 118, 116, 53, 119, 120, 116, 53, 115, 56, 34, 125], timeout_height: Height { revision: 0, height: 0 }, timeout_timestamp: Timestamp { time: Some(Time(PrimitiveDateTime { date: Date { year: 2022, ordinal: 35 }, time: Time { hour: 19, minute: 4, second: 13, nanosecond: 872918905 } })) } } })] } }
[...]
[36mhermes_1  |�[0m 2022-02-04T18:54:43.956578Z ERROR ThreadId(06) send_tx_check{id=r3OuBgBnr_}:send_tx{id=cosmoshub-testnet}:estimate_gas: failed to simulate tx. propagating error to caller: gRPC call failed with status: status: InvalidArgument, message: "failed to execute message; message index: 2: receive packet verification failed: packet sequence (1) already has been received: invalid packet: invalid request", details: [], metadata: MetadataMap { headers: {"date": "Fri, 04 Feb 2022 18:54:43 GMT", "content-type": "application/grpc", "content-length": "0", "strict-transport-security": "max-age=15724800; includeSubDomains"} }
�[36mhermes_1  |�[0m 2022-02-04T18:54:43.957347Z ERROR ThreadId(56) packet_cmd{src_chain=agoric src_port=port-4 src_channel=channel-0 dst_chain=cosmoshub-testnet}: will retry: schedule execution encountered error: failed with underlying error: gRPC call failed with status: status: InvalidArgument, message: "failed to execute message; message index: 2: receive packet verification failed: packet sequence (1) already has been received: invalid packet: invalid request", details: [], metadata: MetadataMap { headers: {"date": "Fri, 04 Feb 2022 18:54:43 GMT", "content-type": "application/grpc", "content-length": "0", "strict-transport-security": "max-age=15724800; includeSubDomains"} } retry_index=1

Complete log is at: https://gist.github.com/michaelfig/ba3eefc15134e3d2aea92c106cad56c4

Note that this problem also runs afoul of simulation errors preventing the flow of packets. Ideally, simulation errors would not interrupt the flow, and instead still send packets to the recipient where they can be reported as acknowledgements with a failure content, so that sender can tell they've made a mistake.

Acceptance Criteria

Packets are relayed successfully.

---

For Admin Use

• Not duplicate issue
• Appropriate labels applied
• Appropriate milestone (priority) applied
• Appropriate contributors tagged
• Contributor assigned/self-assigned

[hu55a1n1]

Related -> #1608