Hermes clear_on_start toggle does not work

[adizere]

Crate

ibc-relayer and ibc-relayer-cli

Summary of Bug

It seems that configuring clear_on_start = false does not work. When this is set to false, Hermes should not try to clear packets at startup. But this is not the case. Instead, we're hardcoding that the clearing should always happen

https://github.com/informalsystems/ibc-rs/blob/aef0e6a92736239d50048e35c73c5eca8c9b7814/relayer/src/link/relay_path.rs#L125

The problem was reported by a relayer operator on Bandchain network. They are probably the only ones using clear_on_start = false (I'm not aware of other operators using false here, and we don't have tests covering this feature, hence this bug went unnoticed for quite some time).

Logs folded here, but not sure they are truly useful. The more important part is the "steps to reproduce" described below.

Logs

Feb 11 02:46:48 ip-172-31-33-244 systemd[1]: Started hermes.
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.204342Z  INFO ThreadId(01) using default configuration from '/home/ubuntu/.hermes/config.toml'
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.205405Z  INFO ThreadId(01) [rest] address not configured, REST server disabled
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.225481Z TRACE ThreadId(01) [injective-1] spawned chain runtime
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.236287Z TRACE ThreadId(07) parsed version specification for <appd> @ -> SDK=0.44.5; Ibc-Go status=Some(Version { major: 2, minor: 0, patch: 2 })
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.236338Z DEBUG ThreadId(07) running diagnostic on version info Specs { sdk_version: Version { major: 0, minor: 44, patch: 5 }, ibc_go_version: Some(Version { major: 2, minor: 0, patch: 2 }) }
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.243593Z  INFO ThreadId(01) [injective-1] chain is healthy
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.245028Z TRACE ThreadId(01) [laozi-mainnet] spawned chain runtime
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.249829Z TRACE ThreadId(08) parsed version specification for bandd 2.3.0@4fe19638b33043eed4dec9861cda40962fb5b2a7 -> SDK=0.44.0; Ibc-Go status=Some(Version { major: 1, minor: 1, patch: 0 })
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.249873Z DEBUG ThreadId(08) running diagnostic on version info Specs { sdk_version: Version { major: 0, minor: 44, patch: 0 }, ibc_go_version: Some(Version { major: 1, minor: 1, patch: 0 }) }
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.253062Z  INFO ThreadId(01) [laozi-mainnet] chain is healthy
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.253120Z  INFO ThreadId(01) scan.chain{chain=injective-1}: scanning chain...
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.253133Z  INFO ThreadId(01) scan.chain{chain=injective-1}: chain uses an allow list, skipping scan for fast startup
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.253139Z  INFO ThreadId(01) scan.chain{chain=injective-1}: allowed ports/channels: oracle/channel-3
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.253158Z  INFO ThreadId(01) scan.chain{chain=injective-1}: querying allowed channels...
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.253168Z  INFO ThreadId(01) scan.chain{chain=injective-1}:scan.channel{port=oracle channel=channel-3}: querying channel...
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.285528Z  INFO ThreadId(01) scan.chain{chain=injective-1}:scan.channel{port=oracle channel=channel-3}: found connection and client connection=connection-6 client=07-tendermint-9
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.285558Z  INFO ThreadId(01) scan.chain{chain=injective-1}:scan.channel{port=oracle channel=channel-3}: querying client... client=07-tendermint-9
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.289257Z  INFO ThreadId(01) scan.chain{chain=injective-1}:scan.channel{port=oracle channel=channel-3}: found counterparty chain for client client=07-tendermint-9 counterparty_chain=laozi-mainnet
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.307842Z  INFO ThreadId(01) scan.chain{chain=injective-1}:scan.channel{port=oracle channel=channel-3}: found counterparty channel counterparty_channel=channel-7
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.317481Z  INFO ThreadId(01) scan.chain{chain=injective-1}:scan.channel{port=oracle channel=channel-3}: found counterparty connection state counterparty_connection_state=OPEN
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.317546Z  INFO ThreadId(01) scan.chain{chain=laozi-mainnet}: scanning chain...
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.317556Z  INFO ThreadId(01) scan.chain{chain=laozi-mainnet}: chain uses an allow list, skipping scan for fast startup
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.317561Z  INFO ThreadId(01) scan.chain{chain=laozi-mainnet}: allowed ports/channels: oracle/channel-7
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.317569Z  INFO ThreadId(01) scan.chain{chain=laozi-mainnet}: querying allowed channels...
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.317577Z  INFO ThreadId(01) scan.chain{chain=laozi-mainnet}:scan.channel{port=oracle channel=channel-7}: querying channel...
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.319784Z  INFO ThreadId(01) scan.chain{chain=laozi-mainnet}:scan.channel{port=oracle channel=channel-7}: found connection and client connection=connection-10 client=07-tendermint-12
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.319806Z  INFO ThreadId(01) scan.chain{chain=laozi-mainnet}:scan.channel{port=oracle channel=channel-7}: querying client... client=07-tendermint-12
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.320522Z  INFO ThreadId(01) scan.chain{chain=laozi-mainnet}:scan.channel{port=oracle channel=channel-7}: found counterparty chain for client client=07-tendermint-12 counterparty_chain=injective-1
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.322189Z  INFO ThreadId(01) scan.chain{chain=laozi-mainnet}:scan.channel{port=oracle channel=channel-7}: found counterparty channel counterparty_channel=channel-3
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.326100Z  INFO ThreadId(01) scan.chain{chain=laozi-mainnet}:scan.channel{port=oracle channel=channel-7}: found counterparty connection state counterparty_connection_state=OPEN
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.326155Z  INFO ThreadId(01) Scanned chains:
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.326162Z  INFO ThreadId(01) # Chain: injective-1
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:   - Client: 07-tendermint-9
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:     * Connection: connection-6
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:       | State: OPEN
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:       | Counterparty state: OPEN
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:       + Channel: channel-3
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:         | Port: oracle
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:         | State: OPEN
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:         | Counterparty: channel-7
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: # Chain: laozi-mainnet
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:   - Client: 07-tendermint-12
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:     * Connection: connection-10
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:       | State: OPEN
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:       | Counterparty state: OPEN
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:       + Channel: channel-7
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:         | Port: oracle
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:         | State: OPEN
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]:         | Counterparty: channel-3
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.327563Z  INFO ThreadId(01) connection connection-6 on chain injective-1 is: Open, state on dest. chain (laozi-mainnet) is: Open
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.327599Z  INFO ThreadId(01) connection connection-6 on chain injective-1 is already open, not spawning Connection worker
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.327608Z  INFO ThreadId(01) no workers were spawn for connection connection-6 on chain injective-1
Feb 11 02:46:48 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:48.327615Z  INFO ThreadId(01) channel channel-3 on chain injective-1 is: OPEN; state on dest. chain (laozi-mainnet) is: OPEN
Feb 11 02:46:58 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:58.545491Z DEBUG ThreadId(01) packet_cmd{src_chain=injective-1 src_port=oracle src_channel=channel-3 dst_chain=laozi-mainnet}: spawning task
Feb 11 02:46:58 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:58.545602Z DEBUG ThreadId(01) packet{src_chain=injective-1 src_port=oracle src_channel=channel-3 dst_chain=laozi-mainnet}: spawning task
Feb 11 02:46:58 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:58.545697Z  INFO ThreadId(01) spawned Packet worker: packet::channel-3/oracle:injective-1->laozi-mainnet
Feb 11 02:46:58 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:58.545711Z  INFO ThreadId(01) no workers spawn for chain injective-1 and channel channel-3
Feb 11 02:46:58 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:58.552528Z  INFO ThreadId(01) connection connection-10 on chain laozi-mainnet is: Open, state on dest. chain (injective-1) is: Open
Feb 11 02:46:58 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:58.552548Z  INFO ThreadId(01) connection connection-10 on chain laozi-mainnet is already open, not spawning Connection worker
Feb 11 02:46:58 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:58.552556Z  INFO ThreadId(01) no workers were spawn for connection connection-10 on chain laozi-mainnet
Feb 11 02:46:58 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:46:58.552562Z  INFO ThreadId(01) channel channel-7 on chain laozi-mainnet is: OPEN; state on dest. chain (injective-1) is: OPEN
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.477636Z DEBUG ThreadId(01) packet_cmd{src_chain=laozi-mainnet src_port=oracle src_channel=channel-7 dst_chain=injective-1}: spawning task
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.477767Z DEBUG ThreadId(01) packet{src_chain=laozi-mainnet src_port=oracle src_channel=channel-7 dst_chain=injective-1}: spawning task
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.477865Z  INFO ThreadId(01) spawned Packet worker: packet::channel-7/oracle:laozi-mainnet->injective-1
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.477879Z  INFO ThreadId(01) no workers spawn for chain laozi-mainnet and channel channel-7
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.483854Z TRACE ThreadId(07) [injective-1] subscribing to query: tm.event = 'NewBlock'
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.485394Z TRACE ThreadId(07) [injective-1] subscribing to query: message.module = 'ibc_client'
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.486884Z TRACE ThreadId(07) [injective-1] subscribing to query: message.module = 'ibc_connection'
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.488292Z TRACE ThreadId(07) [injective-1] subscribing to query: message.module = 'ibc_channel'
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.489691Z TRACE ThreadId(07) [injective-1] subscribed to all queries
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.489872Z DEBUG ThreadId(14) [injective-1] starting event monitor
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.490477Z TRACE ThreadId(08) [laozi-mainnet] subscribing to query: tm.event = 'NewBlock'
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.491256Z TRACE ThreadId(08) [laozi-mainnet] subscribing to query: message.module = 'ibc_client'
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.491755Z TRACE ThreadId(08) [laozi-mainnet] subscribing to query: message.module = 'ibc_connection'
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.492341Z TRACE ThreadId(08) [laozi-mainnet] subscribing to query: message.module = 'ibc_channel'
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.493078Z TRACE ThreadId(08) [laozi-mainnet] subscribed to all queries
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.493172Z DEBUG ThreadId(01) spawning task
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.493260Z DEBUG ThreadId(15) [laozi-mainnet] starting event monitor
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.493308Z DEBUG ThreadId(01) cmd: spawning task
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.493476Z  INFO ThreadId(01) Hermes has started
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.690602Z TRACE ThreadId(15) extracted ibc_client event UpdateClient(UpdateClient { common: Attributes { height: Height { revision: 0, height: 3946171 }, client_id: ClientId("07-tendermint-12"), client_type: Tendermint, consensus_height: Height { revision: 1, height: 7635391 } }, header: Some(Tendermint( Header {...})) })
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.692907Z TRACE ThreadId(15) ibc_channel event: extracted WriteAcknowledgement(WriteAcknowledgement { height: Height { revision: 0, height: 3946171 }, packet: Packet { sequence: Sequence(548797), source_port: PortId("oracle"), source_channel: ChannelId("channel-3"), destination_port: PortId("oracle"), destination_channel: ChannelId("channel-7"), data: [123, 34, 97, 115, 107, 95, 99, 111, 117, 110, 116, 34, 58, 34, 49, 54, 34, 44, 34, 99, 97, 108, 108, 100, 97, 116, 97, 34, 58, 34, 65, 65, 65, 65, 66, 81, 65, 65, 65, 65, 78, 67, 86, 69, 77, 65, 65, 65, 65, 68, 82, 86, 82, 73, 65, 65, 65, 65, 66, 70, 86, 84, 82, 70, 81, 65, 65, 65, 65, 68, 83, 85, 53, 75, 65, 65, 65, 65, 65, 48, 74, 79, 81, 103, 65, 65, 65, 65, 65, 55, 109, 115, 111, 65, 34, 44, 34, 99, 108, 105, 101, 110, 116, 95, 105, 100, 34, 58, 34, 53, 52, 56, 55, 57, 55, 34, 44, 34, 101, 120, 101, 99, 117, 116, 101, 95, 103, 97, 115, 34, 58, 34, 52, 48, 48, 48, 48, 48, 34, 44, 34, 102, 101, 101, 95, 108, 105, 109, 105, 116, 34, 58, 91, 123, 34, 97, 109, 111, 117, 110, 116, 34, 58, 34, 49, 48, 48, 48, 34, 44, 34, 100, 101, 110, 111, 109, 34, 58, 34, 117, 98, 97, 110, 100, 34, 125, 93, 44, 34, 109, 105, 110, 95, 99, 111, 117, 110, 116, 34, 58, 34, 49, 48, 34, 44, 34, 111, 114, 97, 99, 108, 101, 95, 115, 99, 114, 105, 112, 116, 95, 105, 100, 34, 58, 34, 50, 51, 34, 44, 34, 112, 114, 101, 112, 97, 114, 101, 95, 103, 97, 115, 34, 58, 34, 50, 48, 48, 48, 48, 34, 125], timeout_height: Height { revision: 0, height: 0 }, timeout_timestamp: Timestamp { time: Some(Time(PrimitiveDateTime { date: Date { year: 2022, ordinal: 42 }, time: Time { hour: 3, minute: 6, second: 26, nanosecond: 787581891 } })) } }, ack: [123, 34, 114, 101, 115, 117, 108, 116, 34, 58, 34, 101, 121, 74, 121, 90, 88, 70, 49, 90, 88, 78, 48, 88, 50, 108, 107, 73, 106, 111, 105, 78, 68, 103, 119, 78, 84, 73, 119, 78, 105, 74, 57, 34, 125] })
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.693036Z TRACE ThreadId(15) ibc_channel event: extracted WriteAcknowledgement(WriteAcknowledgement { height: Height { revision: 0, height: 3946171 }, packet: Packet { sequence: Sequence(548798), source_port: PortId("oracle"), source_channel: ChannelId("channel-3"), destination_port: PortId("oracle"), destination_channel: ChannelId("channel-7"), data: [123, 34, 97, 115, 107, 95, 99, 111, 117, 110, 116, 34, 58, 34, 49, 54, 34, 44, 34, 99, 97, 108, 108, 100, 97, 116, 97, 34, 58, 34, 65, 65, 65, 65, 66, 103, 65, 65, 65, 65, 82, 77, 86, 85, 53, 66, 65, 65, 65, 65, 65, 49, 86, 84, 86, 65, 65, 65, 65, 65, 82, 84, 81, 49, 74, 85, 65, 65, 65, 65, 66, 69, 70, 85, 84, 48, 48, 65, 65, 65, 65, 68, 81, 49, 74, 80, 65, 65, 65, 65, 65, 49, 78, 85, 87, 65, 65, 65, 65, 65, 65, 55, 109, 115, 111, 65, 34, 44, 34, 99, 108, 105, 101, 110, 116, 95, 105, 100, 34, 58, 34, 53, 52, 56, 55, 57, 56, 34, 44, 34, 101, 120, 101, 99, 117, 116, 101, 95, 103, 97, 115, 34, 58, 34, 52, 48, 48, 48, 48, 48, 34, 44, 34, 102, 101, 101, 95, 108, 105, 109, 105, 116, 34, 58, 91, 123, 34, 97, 109, 111, 117, 110, 116, 34, 58, 34, 49, 48, 48, 48, 34, 44, 34, 100, 101, 110, 111, 109, 34, 58, 34, 117, 98, 97, 110, 100, 34, 125, 93, 44, 34, 109, 105, 110, 95, 99, 111, 117, 110, 116, 34, 58, 34, 49, 48, 34, 44, 34, 111, 114, 97, 99, 108, 101, 95, 115, 99, 114, 105, 112, 116, 95, 105, 100, 34, 58, 34, 50, 51, 34, 44, 34, 112, 114, 101, 112, 97, 114, 101, 95, 103, 97, 115, 34, 58, 34, 50, 48, 48, 48, 48, 34, 125], timeout_height: Height { revision: 0, height: 0 }, timeout_timestamp: Timestamp { time: Some(Time(PrimitiveDateTime { date: Date { year: 2022, ordinal: 42 }, time: Time { hour: 3, minute: 6, second: 26, nanosecond: 787581891 } })) } }, ack: [123, 34, 114, 101, 115, 117, 108, 116, 34, 58, 34, 101, 121, 74, 121, 90, 88, 70, 49, 90, 88, 78, 48, 88, 50, 108, 107, 73, 106, 111, 105, 78, 68, 103, 119, 78, 84, 73, 119, 78, 121, 74, 57, 34, 125] })
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.698255Z TRACE ThreadId(15) extracted ibc_client event UpdateClient(UpdateClient { common: Attributes { height: Height { revision: 0, height: 3946171 }, client_id: ClientId("07-tendermint-21"), client_type: Tendermint, consensus_height: Height { revision: 0, height: 2267474 } }, header: Some(Tendermint( Header {...})) })
Feb 11 02:47:02 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:02.700732Z TRACE ThreadId(15) ibc_channel event: extracted WriteAcknowledgement(WriteAcknowledgement { height: Height { revision: 0, height: 3946171 }, packet: Packet { sequence: Sequence(272), source_port: PortId("ibc-profiles"), source_channel: ChannelId("channel-1"), destination_port: PortId("oracle"), destination_channel: ChannelId("channel-12"), data: [123, 34, 97, 115, 107, 95, 99, 111, 117, 110, 116, 34, 58, 34, 53, 34, 44, 34, 99, 97, 108, 108, 100, 97, 116, 97, 34, 58, 34, 65, 65, 65, 65, 66, 50, 82, 112, 99, 50, 78, 118, 99, 109, 81, 65, 65, 65, 66, 65, 78, 50, 73, 121, 77, 106, 99, 49, 78, 122, 77, 50, 78, 84, 99, 121, 78, 109, 85, 50, 77, 84, 90, 107, 78, 106, 85, 121, 77, 106, 78, 104, 77, 106, 73, 48, 78, 68, 99, 121, 78, 106, 85, 51, 78, 122, 99, 122, 78, 122, 85, 51, 77, 106, 99, 49, 78, 109, 85, 50, 77, 122, 90, 106, 78, 106, 85, 121, 77, 122, 77, 49, 77, 122, 69, 122, 77, 68, 77, 49, 77, 106, 73, 51, 90, 65, 61, 61, 34, 44, 34, 99, 108, 105, 101, 110, 116, 95, 105, 100, 34, 58, 34, 100, 101, 115, 109, 111, 115, 49, 114, 108, 100, 54, 119, 106, 106, 102, 104, 107, 115, 104, 103, 52, 48, 108, 97, 112, 120, 110, 99, 122, 50, 101, 53, 118, 51, 50, 53, 114, 103, 112, 117, 101, 122, 97, 115, 48, 45, 100, 105, 115, 99, 111, 114, 100, 45, 68, 114, 101, 119, 115, 117, 114, 117, 110, 99, 108, 101, 35, 53, 49, 48, 53, 34, 44, 34, 101, 120, 101, 99, 117, 116, 101, 95, 103, 97, 115, 34, 58, 34, 50, 48, 48, 48, 48, 48, 34, 44, 34, 102, 101, 101, 95, 108, 105, 109, 105, 116, 34, 58, 91, 123, 34, 97, 109, 111, 117, 110, 116, 34, 58, 34, 53, 48, 48, 34, 44, 34, 100, 101, 110, 111, 109, 34, 58, 34, 117, 98, 97, 110, 100, 34, 125, 93, 44, 34, 109, 105, 110, 95, 99, 111, 117, 110, 116, 34, 58, 34, 51, 34, 44, 34, 111, 114, 97, 99, 108, 101, 95, 115, 99, 114, 105, 112, 116, 95, 105, 100, 34, 58, 34, 50, 53, 34, 44, 34, 112, 114, 101, 112, 97, 114, 101, 95, 103, 97, 115, 34, 58, 34, 53, 48, 48, 48, 48, 34, 125], timeout_height: Height { revision: 0, height: 0 }, timeout_timestamp: Timestamp { time: Some(Time(PrimitiveDateTime { date: Date { year: 2022, ordinal: 42 }, time: Time { hour: 3, minute: 46, second: 26, nanosecond: 612000000 } })) } }, ack: [123, 34, 114, 101, 115, 117, 108, 116, 34, 58, 34, 101, 121, 74, 121, 90, 88, 70, 49, 90, 88, 78, 48, 88, 50, 108, 107, 73, 106, 111, 105, 78, 68, 103, 119, 78, 84, 73, 119, 79, 67, 74, 57, 34, 125] })
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.294034Z TRACE ThreadId(16) skipping events for 'packet::channel-12/oracle:laozi-mainnet->desmos-mainnet'. reason: filtering is enabled and channel does not match any allowed channels
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.294073Z TRACE ThreadId(16) [client filter] controlling permissions for Channel(ChainId { id: "laozi-mainnet", version: 0 }, PortId("oracle"), ChannelId("channel-7"))
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.302764Z TRACE ThreadId(16) [client filter] controlling permissions for Connection(ChainId { id: "laozi-mainnet", version: 0 }, ConnectionId("connection-10"))
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.310572Z TRACE ThreadId(16) [client filter] controlling permissions for Client(ChainId { id: "laozi-mainnet", version: 0 }, ClientId("07-tendermint-12"))
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.310602Z DEBUG ThreadId(16) [client filter] Allow: relay for client Client(ChainId { id: "laozi-mainnet", version: 0 }, ClientId("07-tendermint-12"))
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.310611Z TRACE ThreadId(16) [client filter] controlling permissions for Client(ChainId { id: "injective-1", version: 1 }, ClientId("07-tendermint-9"))
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.310616Z DEBUG ThreadId(16) [client filter] Allow: relay for client Client(ChainId { id: "injective-1", version: 1 }, ClientId("07-tendermint-9"))
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.310621Z DEBUG ThreadId(16) [client filter] Allow: relay for conn Connection(ChainId { id: "laozi-mainnet", version: 0 }, ConnectionId("connection-10"))
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.310631Z DEBUG ThreadId(16) [client filter] Allow: relay for channel Channel(ChainId { id: "laozi-mainnet", version: 0 }, PortId("oracle"), ChannelId("channel-7")):
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.479282Z TRACE ThreadId(12) packet_cmd{src_chain=laozi-mainnet src_port=oracle src_channel=channel-7 dst_chain=injective-1}: handling command NewBlock { height: Height { revision: 0, height: 3946171 }, new_block: NewBlock { height: Height { revision: 0, height: 3946171 } } }
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.514060Z DEBUG ThreadId(12) packet_cmd{src_chain=laozi-mainnet src_port=oracle src_channel=channel-7 dst_chain=injective-1}:clear{f=false}: packet seq. that still have commitments on laozi-mainnet: 165, 312, 512, 1167, 1362, 1560, 1903, 2509, 2641, 2673 (first 10 shown here; total=3011)
Feb 11 02:47:04 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:04.514096Z DEBUG ThreadId(12) packet_cmd{src_chain=laozi-mainnet src_port=oracle src_channel=channel-7 dst_chain=injective-1}:clear{f=false}: recv packets to send out to injective-1 of the ones with commitments on laozi-mainnet: 165, 312, 512, 1167, 1362, 1560, 1903, 2509, 2641, 2673 (first 10 shown here; total=2787)
Feb 11 02:47:05 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:05.350661Z TRACE ThreadId(10) packet_cmd{src_chain=injective-1 src_port=oracle src_channel=channel-3 dst_chain=laozi-mainnet}: handling command NewBlock { height: Height { revision: 1, height: 7635403 }, new_block: NewBlock { height: Height { revision: 1, height: 7635403 } } }
Feb 11 02:47:09 ip-172-31-33-244 bash[2935599]: 2022-02-11T02:47:09.655568Z DEBUG ThreadId(10) packet_cmd{src_chain=injective-1 src_port=oracle src_channel=channel-3 dst_chain=laozi-mainnet}:clear{f=false}: packet seq. that still have commitments on injective-1: 382, 2831, 2922, 3440, 3441, 3442, 3443, 3444, 3445, 3446 (first 10 shown here; total=4209)... (23 KB left)

Version

v0.11.1

Steps to Reproduce

1. Setup a two chain network using gm. Suppose the two networks and ibc-0 and ibc-1.
2. Setup a channel-0 between the two networks.
3. Trigger and ft-transfer on channel-0 of ibc-0

   • ./target/debug/hermes --json tx raw ft-transfer ibc-1 ibc-0 transfer channel-0 100 -d samoleans -t 1800 -n 1

4. Configure clear_on_start to be false in the config.toml of Hermes.
   • Make sure your log level is set to log_level = 'debug'.
   • Also set clear_interval = 0 to completely disable periodic packet clearing.
5. Do hermes start.
   • Notice the log output and it should be visible that Hermes will clear the outstanding packets.
   • The main indicator of this is the clear{} span appearing in the log lines:

   • 2022-02-15T10:15:09.764808Z INFO ThreadId(01) Hermes has started
     2022-02-15T10:15:19.908308Z DEBUG ThreadId(22) packet_cmd{src_chain=ibc-0 src_port=transfer src_channel=channel-2 dst_chain=ibc-1}:clear{f=false}: packet seq. that still have commitments on ibc-0: 8 (first 10 shown here; total=1)

Under normal circumstances, when clear_on_start = false, Hermes should not immediately clear packets upon startup.

Acceptance Criteria

• the clear_on_start option should translate into the correct Hermes behavior: if set to false, then hermes start should proceed to relaying live packets immediately (instead of relaying old packets)

---

For Admin Use

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

[adizere]

Temporary solution here

https://github.com/informalsystems/ibc-rs/compare/anca/tempfix_noclear?expand=1

The full solution should ensure that clear_on_start option propagates from config.toml down in the RelayPath logic.