Duplicate packets on start

[ancazamfir]

Summary of Bug

When a packet worker is started (triggered by an IBC event) it will submit duplicate transaction triggered by clearing on start. I think we need to use height.decrement() here:
https://github.com/informalsystems/ibc-rs/blob/184a811564d7d699ceb72ad1563f7746a8b98a39/relayer/src/worker/packet.rs#L171

Version

master

Steps to Reproduce

• hermes create channel
• hermes start
• hermes tx raw ft-transfer ibc-1 ibc-0 transfer channel-0 10 -n 1 -o 30 -k user2
• observe the errors for both MsgRecvPacket and MsgAcknowledgement:

2022-04-13T02:00:55.665191Z ERROR ThreadId(40) send_tx_check{id=aatwvhqFEt}:send_tx{id=ibc-0}: broadcast_tx_sync: Response { code: Err(22), data: Data([]), log: Log("packet messages are redundant"), hash: transaction::Hash(6EC112B981392A1EF527FC9FD88B34439D120B06D5E25CF97227E5B26AD3DF6D) }: diagnostic: unknown SDK error: 22

Acceptance Criteria

Should not submit duplicate transactions

---

For Admin Use

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

[adizere]

This is consistent with what we noticed yesterday in the GH action logs --

2022-04-12T10:41:46.595827Z INFO ibc_test_framework::bootstrap::binary::channel: created new chain/client/connection/channel from ibc-0-f172a25a/07-tendermint-3/connection-20/channel-26 to ibc-0-f172a25a/07-tendermint-3/connection-21/channel-27
9513
2022-04-12T10:41:46.684534Z INFO ibc_integration_test::tests::transfer: Sending IBC transfer from chain ibc-0-f172a25a to chain ibc-0-f172a25a with amount of 3625 coin24abc971
9514
2022-04-12T10:41:46.791349Z INFO ibc_integration_test::tests::transfer: Waiting for user on chain B to receive IBC transferred amount of 3625 ibc/B5A62F8D0DA34679952FC47684A3A009FF9F69CD9B2F355BED99A53A92DB6994
9515
2022-04-12T10:41:47.871966Z INFO ibc_test_framework::util::retry: task wallet reach cosmos16d0uef9j7fqf0kdkrzqcejc9cdg6qhh83lmpp4 amount 6786923594663 coin24abc971 succeed after 0 tries
9516
2022-04-12T10:41:48.314294Z INFO packet_cmd{src_chain=ibc-0-f172a25a src_port=transfer src_channel=channel-14 dst_chain=ibc-0-f172a25a}:relay{odata=mmn6qpeuvK ->Destination @0-93; len=1}: ibc_relayer::link::operational_data: assembled batch of 2 message(s)
9517
2022-04-12T10:41:48.330343Z INFO packet_cmd{src_chain=ibc-0-f172a25a src_port=transfer src_channel=channel-14 dst_chain=ibc-0-f172a25a}:relay{odata=mmn6qpeuvK ->Destination @0-93; len=1}: ibc_relayer::link::relay_sender: [Async~>ibc-0-f172a25a] response(s): 1; Ok:241B6A4439196AF789D57260628EEE7682889E2B48A92E36E3E25A00E07662A0
9518
9519
2022-04-12T10:41:48.330458Z INFO packet_cmd{src_chain=ibc-0-f172a25a src_port=transfer src_channel=channel-14 dst_chain=ibc-0-f172a25a}:relay{odata=mmn6qpeuvK ->Destination @0-93; len=1}: ibc_relayer::link::relay_path: success
9520
2022-04-12T10:41:48.547240Z INFO packet_cmd{src_chain=ibc-0-f172a25a src_port=transfer src_channel=channel-14 dst_chain=ibc-0-f172a25a}: ibc_relayer::link::relay_path: found zero unprocessed SendPacket events on source chain, nothing to do
9521
2022-04-12T10:41:48.810604Z INFO packet_cmd{src_chain=ibc-0-f172a25a src_port=transfer src_channel=channel-14 dst_chain=ibc-0-f172a25a}:relay{odata=QEEL3x3_0d ->Destination @0-93; len=1}: ibc_relayer::link::operational_data: assembled batch of 2 message(s)
9522
2022-04-12T10:41:48.824268Z ERROR send_tx{id=ibc-0-f172a25a}: ibc_relayer::chain::cosmos: broadcast_tx_sync: Response { code: Err(22), data: Data([]), log: Log("packet messages are redundant"), hash: transaction::Hash(71F03E0534FDB1C0C35F39A3328A3BEDD0B13CB5932A2861C380830C4EA9A62D) }: diagnostic: unknown SDK error: 22

[seanchen1991]

Neither @adizere or I were able to reproduce this issue locally. It's hard to say whether this issue is only exhibited on a particular version of Hermes and/or Gaia, but we both tried with Hermes versions 0.14 and 0.15, as well as Gaia v7, to no avail.

We also attempted to reproduce the error using the CI commands that yielded the logs that Adi posted above, but that also bore no fruit.

@ancazamfir are you able to reproduce this again and/or provide additional hints/context so that we can reproduce it on our ends?

[ancazamfir]

Here are the steps I used just now (on master with latest eae0afd):

1. start two chains with gaia v7.0.0
   ./scripts/dev-env ~/.hermes/config.toml ibc-0 ibc-1
2. create channel
   hermes create channel ibc-0 --port-a transfer --port-b transfer --new-client-connection -c ibc-1
3. start hermes
   hermes start
4. send one packet
   hermes tx raw ft-transfer ibc-0 ibc-1 transfer channel-0 10 -n 1 -o 4000 -k user2

It doesn't happen all the time, you need to repeat steps 3. and 4. Here are the hermes logs:

2022-05-25T20:30:20.257238Z  INFO ThreadId(01) telemetry service running, exposing metrics at http://127.0.0.1:3001/metrics
2022-05-25T20:30:20.257395Z  INFO ThreadId(01) [rest] address not configured, REST server disabled
2022-05-25T20:30:20.273521Z  INFO ThreadId(01) [ibc-0] chain is healthy
2022-05-25T20:30:20.286218Z  INFO ThreadId(01) [ibc-1] chain is healthy
2022-05-25T20:30:20.286428Z  INFO ThreadId(01) scan.chain{chain=ibc-0}: scanning chain...
2022-05-25T20:30:20.286481Z  INFO ThreadId(01) scan.chain{chain=ibc-0}: scanning chain for all clients, connections and channels
2022-05-25T20:30:20.286511Z  INFO ThreadId(01) scan.chain{chain=ibc-0}: scanning all clients...
2022-05-25T20:30:20.288686Z  INFO ThreadId(01) scan.chain{chain=ibc-0}:scan.client{client=07-tendermint-0}: scanning client...
2022-05-25T20:30:20.292540Z  INFO ThreadId(01) scan.chain{chain=ibc-0}:scan.client{client=07-tendermint-0}:scan.connection{connection=connection-0}: scanning connection...
2022-05-25T20:30:20.298693Z  INFO ThreadId(01) scan.chain{chain=ibc-1}: scanning chain...
2022-05-25T20:30:20.298733Z  INFO ThreadId(01) scan.chain{chain=ibc-1}: scanning chain for all clients, connections and channels
2022-05-25T20:30:20.298755Z  INFO ThreadId(01) scan.chain{chain=ibc-1}: scanning all clients...
2022-05-25T20:30:20.300765Z  INFO ThreadId(01) scan.chain{chain=ibc-1}:scan.client{client=07-tendermint-0}: scanning client...
2022-05-25T20:30:20.303327Z  INFO ThreadId(01) scan.chain{chain=ibc-1}:scan.client{client=07-tendermint-0}:scan.connection{connection=connection-0}: scanning connection...
2022-05-25T20:30:20.308317Z  INFO ThreadId(01) Scanned chains:
2022-05-25T20:30:20.308343Z  INFO ThreadId(01) # Chain: ibc-0
  - Client: 07-tendermint-0
    * Connection: connection-0
      | State: OPEN
      | Counterparty state: OPEN
      + Channel: channel-0
        | Port: transfer
        | State: OPEN
        | Counterparty: channel-0
# Chain: ibc-1
  - Client: 07-tendermint-0
    * Connection: connection-0
      | State: OPEN
      | Counterparty state: OPEN
      + Channel: channel-0
        | Port: transfer
        | State: OPEN
        | Counterparty: channel-0

2022-05-25T20:30:20.308511Z  INFO ThreadId(01) connection is Open, state on destination chain is Open chain=ibc-0 connection=connection-0 counterparty_chain=ibc-1
2022-05-25T20:30:20.308542Z  INFO ThreadId(01) connection is already open, not spawning Connection worker chain=ibc-0 connection=connection-0
2022-05-25T20:30:20.308578Z  INFO ThreadId(01) no connection workers were spawn chain=ibc-0 connection=connection-0
2022-05-25T20:30:20.308618Z  INFO ThreadId(01) channel is OPEN, state on destination chain is OPEN chain=ibc-0 counterparty_chain=ibc-1 channel=channel-0
2022-05-25T20:30:20.314160Z  INFO ThreadId(01) no channel workers were spawned chain=ibc-0 channel=channel-0
2022-05-25T20:30:20.314364Z  INFO ThreadId(01) spawning Wallet worker: wallet::ibc-0
2022-05-25T20:30:20.314458Z  INFO ThreadId(01) connection is Open, state on destination chain is Open chain=ibc-1 connection=connection-0 counterparty_chain=ibc-0
2022-05-25T20:30:20.314485Z  INFO ThreadId(01) connection is already open, not spawning Connection worker chain=ibc-1 connection=connection-0
2022-05-25T20:30:20.314512Z  INFO ThreadId(01) no connection workers were spawn chain=ibc-1 connection=connection-0
2022-05-25T20:30:20.314538Z  INFO ThreadId(01) channel is OPEN, state on destination chain is OPEN chain=ibc-1 counterparty_chain=ibc-0 channel=channel-0
2022-05-25T20:30:20.321306Z  INFO ThreadId(01) no channel workers were spawned chain=ibc-1 channel=channel-0
2022-05-25T20:30:20.321472Z  INFO ThreadId(01) spawning Wallet worker: wallet::ibc-1
2022-05-25T20:30:20.330954Z  INFO ThreadId(01) Hermes has started
2022-05-25T20:30:30.361330Z  INFO ThreadId(50) packet_cmd{src_chain=ibc-1 src_port=transfer src_channel=channel-0 dst_chain=ibc-0}:relay{odata=676cd881 ->Destination @1-765; len=1}: assembled batch of 2 message(s)
2022-05-25T20:30:30.374212Z  INFO ThreadId(50) packet_cmd{src_chain=ibc-1 src_port=transfer src_channel=channel-0 dst_chain=ibc-0}:relay{odata=676cd881 ->Destination @1-765; len=1}: [Async~>ibc-0] response(s): 1; Ok:73EBA7C876639A845834D8BA28E212B0F92BF987022431AF319375F6ED61E427

2022-05-25T20:30:30.374275Z  INFO ThreadId(50) packet_cmd{src_chain=ibc-1 src_port=transfer src_channel=channel-0 dst_chain=ibc-0}:relay{odata=676cd881 ->Destination @1-765; len=1}: success
2022-05-25T20:30:32.565781Z  INFO ThreadId(61) packet_cmd{src_chain=ibc-0 src_port=transfer src_channel=channel-0 dst_chain=ibc-1}:relay{odata=f9309905 ->Destination @0-779; len=1}: assembled batch of 2 message(s)
2022-05-25T20:30:32.579241Z  INFO ThreadId(61) packet_cmd{src_chain=ibc-0 src_port=transfer src_channel=channel-0 dst_chain=ibc-1}:relay{odata=f9309905 ->Destination @0-779; len=1}: [Async~>ibc-1] response(s): 1; Ok:9BED1BEB1BBEA34458886E3814E8743718A1032C86A279D9454029A658CEB915

2022-05-25T20:30:32.579302Z  INFO ThreadId(61) packet_cmd{src_chain=ibc-0 src_port=transfer src_channel=channel-0 dst_chain=ibc-1}:relay{odata=f9309905 ->Destination @0-779; len=1}: success
2022-05-25T20:30:33.402804Z  INFO ThreadId(61) packet_cmd{src_chain=ibc-0 src_port=transfer src_channel=channel-0 dst_chain=ibc-1}: pulled packet data for 1 events; events_total=1 events_left=0
2022-05-25T20:30:33.433985Z  INFO ThreadId(61) packet_cmd{src_chain=ibc-0 src_port=transfer src_channel=channel-0 dst_chain=ibc-1}:relay{odata=relay pending packets ->Destination @0-779; len=1}: assembled batch of 2 message(s)
2022-05-25T20:30:33.444180Z ERROR ThreadId(41) send_tx_with_account_sequence_retry{id=ibc-1}: broadcast_tx_sync: Response { code: Err(22), data: Data([]), log: Log("packet messages are redundant"), hash: transaction::Hash(C471BB707696D91ABF6388949EBA41119BB6997AEBCFD166F12E3F12AC8F7327) }: diagnostic: unknown SDK error: 22
2022-05-25T20:30:33.444309Z  INFO ThreadId(61) packet_cmd{src_chain=ibc-0 src_port=transfer src_channel=channel-0 dst_chain=ibc-1}:relay{odata=relay pending packets ->Destination @0-779; len=1}: [Async~>ibc-1] response(s): 1; Err(22):C471BB707696D91ABF6388949EBA41119BB6997AEBCFD166F12E3F12AC8F7327

2022-05-25T20:30:33.444359Z  INFO ThreadId(61) packet_cmd{src_chain=ibc-0 src_port=transfer src_channel=channel-0 dst_chain=ibc-1}:relay{odata=relay pending packets ->Destination @0-779; len=1}: success

[seanchen1991]

What does the user2_config.toml file look like?

[ancazamfir]

What does the user2_config.toml file look like?

I removed it from the instructions but in general I use the user2 key for CLIs and testkey for the relayer started with hermes start. So in my case it's identical to ~/.hermes/config.toml used by hermes start except key_name = 'user2' instead of key_name = 'testkey' for both chains.

One more comment on the repro, you might have more luck with flipping steps 3 and 4, that is send the packet and immediately start the relayer (before you even see the ft-transfer CLI confirmation).