Hermes resubmits already received packet

[lyqingye]

Crate

hermes

Summary of Bug

 worker: 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 (8472) already has been received: invalid packet: invalid request", details: [], metadata: MetadataMap { headers: {"content-type": "application/grpc"} }

Ref: #1479

This bug still appears with v0.9.0

Version

v0.9.0

Steps to Reproduce

Acceptance Criteria

---

For Admin Use

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

[adizere]

Hey, thanks for submitting this bug report.

The log output is quite minimal, it's not clear if this is an error from gas simulation step (which is OK), or from tx submission step (which would be a bug indeed).

Can you provide more context to your logs? Thank you.

[lyqingye]

Hey, adizere
The direct cause of this error is send msgs-batch (estimate_gas) The MsgRecvPacket message with the same sequence is contained in batch.

[lyqingye]

I try to add log code at send_tx like that

fn send_tx(&mut self, proto_msgs: Vec<Any>) -> Result<Response, Error> {
        for msg in &proto_msgs {
            if msg.type_url == "/ibc.core.channel.v1.MsgRecvPacket" {
                let packet: MsgRecvPacket  = prost::Message::decode(msg.value.as_slice()).unwrap();
                println!("{:?}",packet);
            }
        }

when this error occurs，the output of the above code is

MsgRecvPacket { packet: Some(Packet { sequence: 7, source_port: "oracle", source_channel: "channel-0",.......
MsgRecvPacket { packet: Some(Packet { sequence: 7, source_port: "oracle", source_channel: "channel-0",.......

this method is called twice in the same NewBlock, I can't reproduce the problem, but it does exist
https://github.com/informalsystems/ibc-rs/blob/master/relayer/src/event/rpc.rs#L13

[adizere]

I see, thank you!

One more question: Do you happen to know if this problem with duplicate sequences appears for a certain network? Or did you notice the problem for any network?

Any additional feedback would be welcome, since it still seems difficult for us to reproduce & fix this based on the discussion so far.

[lyqingye]

I see, thank you!

One more question: Do you happen to know if this problem with duplicate sequences appears for a certain network? Or did you notice the problem for any network?

Any additional feedback would be welcome, since it still seems difficult for us to reproduce & fix this based on the discussion so far.

bandprotocol , it produce ibc-packet at Endblock , only in this scenario can the above situation occur. At present, I am gradually narrowing the scope of bugs

[lyqingye]

add some log at get_all_events

pub fn get_all_events(
    chain_id: &ChainId,
    result: RpcEvent,
    latest_height: u64,
) -> Result<Vec<(Height, IbcEvent)>, String> {
    let mut vals: Vec<(Height, IbcEvent)> = vec![];

    match &result.data {
        RpcEventData::NewBlock { block, .. } => {

            let height = Height::new(
                ChainId::chain_version(chain_id.to_string().as_str()),
                u64::from(block.as_ref().ok_or("tx.height")?.header.height),
            );

            if height.revision_height <= latest_height {
                return Ok(vals);
            }
            tracing::info!("Chain:{:?} height:{:?}",chain_id,height);

log output, same thread call twice

2021-12-01T02:07:15.849061Z  INFO ThreadId(16) Chain:ChainId { id: "bandchain", version: 0 } height:Height { revision: 0, height: 2279 }
2021-12-01T02:07:15.852507Z  INFO ThreadId(16) Chain:ChainId { id: "bandchain", version: 0 } height:Height { revision: 0, height: 2279 }

now, I use a temporary solution: filter the same messages when sending msgs in same batch.
this is not a good solution. I will continue to track this problem when I have time

[lyqingye]

Hey @adizere I found the cause of the problem

https://github.com/informalsystems/ibc-rs/blob/master/relayer/src/event/monitor.rs#L103

 pub fn all() -> Vec<Query> {
        // Note: Tendermint-go supports max 5 query specifiers!
        vec![
            new_block(),
            ibc_client(),
            ibc_connection(),
            ibc_channel(),
            // This will be needed when we send misbehavior evidence to full node
            // Query::eq("message.module", "evidence"),
        ]
    }

hermes EventMonitor Subscribe NewBlock and Channel Events Topic, Bandchain Produce SendPacket Ibc Event at NewBlock Events, so Hermes captured the same SendPacket event from both topics.

Try the following steps:

1. try subscribe ws://rpc.laozi1.bandchain.org/websocket (I using postman to subscribe websocket)

{
    "jsonrpc": "2.0",
    "method": "subscribe",
    "id": 0,
    "params": {
        "query": "message.module='ibc_channel'"
    }
}

2. view log output when dest chain produce IbcPacket at BeginBlock/EndBlock

{ "jsonrpc": "2.0", "id": 0, "result": { "query": "message.module='ibc_channel'", "data": { "type": "tendermint/event/NewBlockHeader", "value": { "header":

{ "jsonrpc": "2.0", "id": 0, "result": { "query": "message.module='ibc_channel'", "data": { "type": "tendermint/event/NewBlock", "value": { "block":

{ "jsonrpc": "2.0", "id": 0, "result": { "query": "message.module='ibc_channel'", "data": { "type": "tendermint/event/Tx", "value": 

conclution:

when SendPacket produce at BeginBlock/EndBlock and websocket subscribe condition is "message.module='ibc_channel'"
you will get the NewBlock Event.
so when you subscribe new_block and message.module='ibc_channel'" topic at same time, you will get two NewBlock events, so Hermes parses the two NewBlock events and gets two identical SendPacket events.

It seems that this problem only occurs in the lower version of Cosmos-SDK, which is not found in the latest Cosmos-Hub

solution

filter RpcEvent.query string at get_all_events

pub fn get_all_events(
    chain_id: &ChainId,
    result: RpcEvent,
) -> Result<Vec<(Height, IbcEvent)>, String> {
    let mut vals: Vec<(Height, IbcEvent)> = vec![];

    match &result.data {
        RpcEventData::NewBlock { block, .. } => {
           // filter NewBlock query string
            if result.query == queries::new_block().to_string() {
                let height = Height::new(
                    ChainId::chain_version(chain_id.to_string().as_str()),
                    u64::from(block.as_ref().ok_or("tx.height")?.header.height),
                );

                vals.push((height, ClientEvents::NewBlock::new(height).into()));
                if let Some(events) = &result.events {
                    let ibc_events =
                        send_packet_from_block_events(height, events.clone().into_iter().collect());
                    if !ibc_events.is_empty() {
                        vals.extend(ibc_events);
                    }
                }
            }
        }

now hermes works normally!
I'm a beginner. My solution is temporary, If there is a better solution, please share！

[adizere]

so when you subscribe new_block and message.module='ibc_channel'" topic at same time, you will get two NewBlock events, so Hermes parses the two NewBlock events and gets two identical SendPacket events.

That's quite a subtle bug. Your solution is pretty good I would say, and the debugging part even more so, thanks for sharing these findings with us!

It seems that this problem only occurs in the lower version of Cosmos-SDK, which is not found in the latest Cosmos-Hub

This is very interesting, and makes me wonder if it should be a priority to include a permanent fix in Hermes for this problem, if at all. It's a matter of time until Bandchain also updates their SDK version and then the problem will disappear. That being said, we are pushing to releasing a couple of major improvements in a new version, and it's unlikely we'll have the capacity to fix this in the next release (#1648), but we'll keep it on our radar.

I assume you're running a forked version of Hermes. So it's not a problem if this fix is delayed, no? Let me know otherwise and maybe we can include it. Thank you for you understanding.

[dualsystems]

two same txn in one block:
https://www.mintscan.io/iris/txs/F388151AF2817A8B3F6948455D80E914B7D0459C4D28960D36694378C910D047
https://www.mintscan.io/iris/txs/1E8C05E7D77A864018AFC6154C7C07DBDA003F723526A2B9F6A70C831A7AE003

it's normal situation?

[lyqingye]

so when you subscribe new_block and message.module='ibc_channel'" topic at same time, you will get two NewBlock events, so Hermes parses the two NewBlock events and gets two identical SendPacket events.

That's quite a subtle bug. Your solution is pretty good I would say, and the debugging part even more so, thanks for sharing these findings with us!

It seems that this problem only occurs in the lower version of Cosmos-SDK, which is not found in the latest Cosmos-Hub

This is very interesting, and makes me wonder if it should be a priority to include a permanent fix in Hermes for this problem, if at all. It's a matter of time until Bandchain also updates their SDK version and then the problem will disappear. That being said, we are pushing to releasing a couple of major improvements in a new version, and it's unlikely we'll have the capacity to fix this in the next release (#1648), but we'll keep it on our radar.

I assume you're running a forked version of Hermes. So it's not a problem if this fix is delayed, no? Let me know otherwise and maybe we can include it. Thank you for you understanding.

Yes, I running a forked version of Hermes, but I still hope Hermes can permanently fix the problem. because this is a problem caused by the SDK and will affect all chains using this version.

[romac]

@lyqingye Can you please test with this branch and see if it fixes the problem? (cf. #1844)

[lyqingye]

#1844

I didn't try the code for this branch, but I reviewed it #1852 The code is consistent with the code I repaired, so it seems to be no problem