Support for incremental packet clearing #2167

adizere · 2022-05-02T13:14:06Z

Closes: #2087

Basic manual tests

This PR fixes an issue with Hermes taking a very long time, being unresponsive or being unable to clear packets in production. We cannot reproduce the production conditions, so the manual tests will be more rudimental.

Setup

Use gm to create and start two networks
- create a channel between them
- create channel ibc-0 -c ibc-1 --port-a transfer --port-b transfer --new-client-connection
gm hermes config and gm hermes keys

Adjust the gas parameters to allow large transactions

- gas_price = { price = 0.001, denom = 'stake' }
+ gas_price = { price = 0.01, denom = 'stake' }
- max_gas = 1000000
+ max_gas = 10000000```

do the above for both of your networks

Test with this branch

Create 2000 ft token transfers
- hermes tx raw ft-transfer ibc-0 ibc-1 transfer channel-0 9999 -o 1000 -n 2000
- this should take 10~20 seconds or so depending on your setup
Clear the outstanding packets
- hermes clear packets ibc-1 transfer channel-0
- every so often, the output will show the progress report

2022-05-02T13:41:10.560540Z INFO ThreadId(01) PacketRecvCmd{src_chain=ibc-1 src_port=transfer src_channel=channel-0 dst_chain=ibc-0}: built packet data for 50 events total=2010 left=1810

After all the event data is pulled from the chain, Hermes proceeds to submit the transactions one by one

2022-05-02T13:43:24.955983Z INFO ThreadId(01) PacketRecvCmd{src_chain=ibc-1 src_port=transfer src_channel=channel-0 dst_chain=ibc-0}:relay{odata=2diAXcipxM ->Destination @1-113; len=50}: success
2022-05-02T13:43:24.956192Z INFO ThreadId(01) PacketRecvCmd{src_chain=ibc-1 src_port=transfer src_channel=channel-0 dst_chain=ibc-0}: ready to fetch a scheduled op. data with batch of size 50 targeting Destination
2022-05-02T13:43:24.964239Z INFO ThreadId(01) PacketRecvCmd{src_chain=ibc-1 src_port=transfer src_channel=channel-0 dst_chain=ibc-0}:relay{odata=-_50M9IdL2 ->Destination @1-113; len=50}: optimistically resolved consensus_state_height upper_bound=1-114 result=1-35
2022-05-02T13:43:24.984645Z INFO ThreadId(01) PacketRecvCmd{src_chain=ibc-1 src_port=transfer src_channel=channel-0 dst_chain=ibc-0}:relay{odata=-_50M9IdL2 ->Destination @1-113; len=50}: assembled batch of 51 message(s)
2022-05-02T13:43:25.048935Z INFO ThreadId(21) wait_for_block_commits: waiting for commit of tx hashes(s) 7750973471BC89F98D4C70876E15E79A908FEC4B37CA8DDD4E25DF44B6CD360C, 9DB59FD0337166E4EAA87CB2ED7F5BC6CE9B660E167A12D2F718A74AE613D252 id=ibc-0
2022-05-02T13:43:30.081510Z INFO ThreadId(01) PacketRecvCmd{src_chain=ibc-1 src_port=transfer src_channel=channel-0 dst_chain=ibc-0}:relay{odata=-_50M9IdL2 ->Destination @1-113; len=50}: [Sync->ibc-0] result events:

Test with `master` branch

Create 2000 ft token transfers
- hermes tx raw ft-transfer ibc-0 ibc-1 transfer channel-0 9999 -o 1000 -n 2000
- this should take 10~20 seconds or so depending on your setup
1. Clear the outstanding packets
- hermes clear packets ibc-1 transfer channel-0
- This time, the process will take a long time to build the packet data for all 2000 packets in a single query
- This will be reflected in a very long initial waiting time. On my setup this takes ~1 minute, but in production it can be on the order of tens of minutes (which can cause subsequent errors)

2022-05-02T13:48:46.040035Z INFO ThreadId(01) using default configuration from '/Users/adi/.hermes/config.toml'
2022-05-02T13:49:32.861348Z INFO ThreadId(01) PacketRecvCmd{src_chain=ibc-1 src_port=transfer src_channel=channel-0 dst_chain=ibc-0}: found unprocessed SendPacket events for [Sequence(2011), Sequence(2012), Sequence(2013), Sequence(2014), Sequence(2015), Sequence(2016), Sequence(2017), Sequence(2018), Sequence(2019), Sequence(2020)] (first 10 shown here; total=2000)

PR author checklist:

Added changelog entry, using unclog.
Added tests: integration (for Hermes) or unit/mock tests (for modules).
Linked to GitHub issue.
Updated code comments and documentation (e.g., docs/).

Reviewer checklist:

Reviewed Files changed in the GitHub PR explorer.
Manually tested (in case integration/unit/mock tests are absent).

lyqingye · 2022-05-02T14:25:10Z

hi @adizere

I read your PR, and the main change is that you divide the build packet data into multiple batches, each with a size of 50. I use my setup for testing. 10000 packets are generated at one tx. It can be seen from the log that the average cost of building packet data for 50 events is 2.5s(that is take much time)
When Hermes successfully builds 10000 packet data and fails in the send TX process (account sequence mismatch), Hermes will rebuild the non relayed packets again.

lyqingye · 2022-05-02T14:46:44Z

I try to add events store(for improve performance query_txs) to my branch , it clear 10000packet, only take 2min.
however, storing events takes a lot of space. It takes 20m for 20000 packets, including send packets and write ack events. so I wrote a command to clear the relayed events!

adizere · 2022-05-02T15:01:38Z

Thanks for the feedback!

When Hermes successfully builds 10000 packet data and fails in the send TX process (account sequence mismatch), Hermes will rebuild the non relayed packets again.

It's not clear if this is the expected behavior or it's unexpected (i.e., a problem). Could you clarify?

I try to add events store(for improve performance query_txs) to my branch , it clear 10000packet, only take 2min.
however, storing events takes a lot of space. It takes 20m for 10000 packets, including send packets and write ack events. so I wrote a command to clear the relayed events!

This is impressive! Do you use this approach in production? Also: how much space and time does it take exactly?

Is it 20Megabytes for 10.000 packets?
How much time?

lyqingye · 2022-05-02T15:25:35Z

Thanks for the feedback!

When Hermes successfully builds 10000 packet data and fails in the send TX process (account sequence mismatch), Hermes will rebuild the non relayed packets again.

It's not clear if this is the expected behavior or it's unexpected (i.e., a problem). Could you clarify?

I try to add events store(for improve performance query_txs) to my branch , it clear 10000packet, only take 2min.
however, storing events takes a lot of space. It takes 20m for 10000 packets, including send packets and write ack events. so I wrote a command to clear the relayed events!

This is impressive! Do you use this approach in production? Also: how much space and time does it take exactly?

Is it 20Megabytes for 10.000 packets?

How much time?

The process of clear packet is as follows:
query_unreceived_ packets -> build_packet_events -> genertate_msgs_from_events -> send_msgs
when a send_msgs failed , the whole process will restart. I don't know why the sequence mismatch error occurs.

Events store takes 20MB to store 20000 packets（10000send_packet + 10000write_ack）
It takes about 1 ~ 2s（or faster） to query 10000 packets from store

your can use my branch for testing

setup chain config is:

max_msg_num=100
# enable event store 
enable_event_store=true
# rpc poll interval for event store fetching events 
event_store_rpc_poll_interval="500ms"
# wallet balance decimal place , use for wallet balances metrics 
decimal_place=6

relayer-cli/src/conclude.rs

seanchen1991 · 2022-05-02T20:06:21Z

relayer/src/chain/counterparty.rs

-
-    let (commit_sequences, _) = commitments_on_chain(
+    path: &PathIdentifiers,
+) -> Result<(Vec<u64>, Height), Error> {


Can we update the doc comment for this method to detail the new return type? It would also be helpful if the doc comment explained why the Height is returned in the Ok case.

Perhaps even introduce a struct in place of the tuple, and a newtype for the u64 while we are at it?

Good suggestions, thanks! I'm on it.

Can we update the doc comment for this method to detail the new return type? It would also be helpful if the doc comment explained why the Height is returned in the Ok case.

fixed

Perhaps even introduce a struct in place of the tuple, and a newtype for the u64 while we are at it?

Maybe we do it in a different PR?

Agree let's do it in a separate PR.
I started working on this but it wasn't as easy as it sounds. Two complications are that:

A struct already exists that could do the job, but that needs to be moved from relayer-cli to relayer crate and some adaptations are necessary
https://github.com/informalsystems/ibc-rs/blob/f7cbe1cfea7f4b7aeb1bf0e99a1791f46abb2e89/relayer-cli/src/commands/query/packet/acks.rs#L16-L19

the method unreceived_packets has multiple uses and we have adapt all callers if we change its signature

relayer/src/chain/counterparty.rs

relayer/src/foreign_client.rs

lyqingye · 2022-05-04T06:33:27Z

This is the scenario of relaying 2000 packets (using event store). In the generate-opdata phase check whether the packets are already handled
why they are checked again in the refresh schedule,

adizere · 2022-05-04T08:51:14Z

why they are checked again in the refresh schedule,

Currently, the "generate" and the "refresh" phases are completely decoupled. This means there may be several minutes that elapse between the two phases. For this reason, the "refresh" phase double-checks that something was not relayed (by another relayer instance) or the packet did not time-out (since it was generated).

Does this make sense?

This is a place where we can optimize things and I can imagine we can skip the "refresh" in some cases. But we have not experimented with this idea yet.

Ref: #1971 (comment)

relayer/src/link/cli.rs

ancazamfir

I left some review comments and addressed them in 2775ed0 if you want to take a look. I tested quite a bit with this and looks good, encountering still issues with seq mismatch during simulation but not made worse by these changes.

relayer/src/foreign_client.rs

relayer/src/link/relay_path.rs

relayer/src/link/cli.rs

relayer/src/link/relay_path.rs

adizere · 2022-05-12T14:51:57Z

@ancazamfir the branch is now even with master and I undid the foreign_client.rs changes.

Co-authored-by: Anca Zamfir <[email protected]>

ancazamfir

lgtm, great stuff @adizere !!!
Tested all scenarios I could think of and things look good for this issue. There are still things to improve but not here.
I opened #2211 for the redundant client updates that cause not only the warning message and more fees to pe paid by hermes.

Also there is the issue of fragmenting in batches even earlier, on packet commitment query as this might also take a long time (i couldn't find the issue for this but i believe there is one?)

most concerns will be addressed in a separate PR

* Added docs for unreceived_acknowledgements and unreceived_packets * Flipped order of sentences * First iteration for informalsystems#2087; packet-recv works, packet-ack left * Incremental processing of packet-ack relaying * Added consensus_state_height_bounded with optimistic path * Nits * Simplified progress tracking * Comment cleanup * fmt and better logs * Document the alternative path in consensus_state_height_bounded * renamed method to make it more explicit h/t SeanC * better var name * Added workaround to tonic::code inconsistencies. Ref: informalsystems#1971 (comment) * refactored the packet query methods * Refactored CLIs for incremental relaying * Experiment * Fix for packet send for non-zero delay * Using app status instead of network status * fmt * Undoing unnecessary chenges on foreign_client.rs * Removed outdated comments * Apply suggestions from code review Co-authored-by: Anca Zamfir <[email protected]> * Small refactor in cli.rs * Address review comments * Remove duplicate code * Undo one-chain change * Fix documentation * Changelog Co-authored-by: Anca Zamfir <[email protected]> Co-authored-by: Anca Zamfir <[email protected]>

adizere added 10 commits April 28, 2022 13:01

Added docs for unreceived_acknowledgements and unreceived_packets

b21a57a

Flipped order of sentences

0c2426f

Merge branch 'master' into adi/2087

756de1a

First iteration for #2087; packet-recv works, packet-ack left

027a230

Incremental processing of packet-ack relaying

02874c1

Added consensus_state_height_bounded with optimistic path

f89a7bc

Merge branch 'master' into adi/2087

2158e3c

Nits

7cb0da8

Simplified progress tracking

02a909f

Comment cleanup

0721d14

adizere requested review from ancazamfir and romac as code owners May 2, 2022 13:14

adizere mentioned this pull request May 2, 2022

Hermes takes a very long time to clear high number of pending packets #2087

Closed

6 tasks

fmt and better logs

2d22ddc

adizere assigned mircea-c and lyqingye May 2, 2022

seanchen1991 previously requested changes May 2, 2022

View reviewed changes

adizere added 3 commits May 4, 2022 11:20

Document the alternative path in consensus_state_height_bounded

be4e626

renamed method to make it more explicit h/t SeanC

8999ff5

better var name

64a4531

This was referenced May 4, 2022

Make the Hermes CLI output less verbose #2179

Open

Connection and channel handshake fails with non-batching transactions #1971

Closed

adizere added 2 commits May 4, 2022 12:13

Added workaround to tonic::code inconsistencies.

7fd032b

Ref: #1971 (comment)

refactored the packet query methods

7f79e21

ancazamfir self-assigned this May 9, 2022

adizere mentioned this pull request May 9, 2022

Insert ClientUpdate message into every transaction when splitting a message batch #2191

Closed

7 tasks

seanchen1991 reviewed May 10, 2022

View reviewed changes

relayer/src/link/cli.rs Outdated Show resolved Hide resolved

ancazamfir requested changes May 11, 2022

View reviewed changes

adizere mentioned this pull request May 12, 2022

Add a gRPC endpoint for fetching consensus state heights cosmos/ibc-go#798

Closed

3 tasks

adizere and others added 7 commits May 12, 2022 15:12

Experiment

150a593

Fix for packet send for non-zero delay

65f686c

Using app status instead of network status

b1f5144

Merge branch 'master' into adi/2087

647d269

fmt

e13f264

Undoing unnecessary chenges on foreign_client.rs

0cede45

Removed outdated comments

81623a1

Apply suggestions from code review

2d7ac6a

Co-authored-by: Anca Zamfir <[email protected]>

adizere requested a review from ancazamfir May 12, 2022 16:16

adizere and others added 5 commits May 12, 2022 18:16

Small refactor in cli.rs

bc3bab4

Address review comments

e6748b3

Remove duplicate code

99e8faa

Undo one-chain change

ff010e5

Fix documentation

74cfb6b

ancazamfir approved these changes May 13, 2022

View reviewed changes

adizere requested a review from seanchen1991 May 13, 2022 12:11

romac mentioned this pull request May 13, 2022

Introduce a couple new types for the data returned by unreceived_packets #2212

Closed

Changelog

13742f7

adizere merged commit 39606d2 into master May 13, 2022

adizere deleted the adi/2087 branch May 13, 2022 13:02

adizere mentioned this pull request May 20, 2022

Default ordering in gRPC responses assumes lexicographic values of Height, not numerical value cosmos/ibc-go#1399

Open

adizere mentioned this pull request Sep 14, 2022

Consider logging the packets involved in the clear packets CLI flow #2623

Closed

6 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Support for incremental packet clearing #2167

Support for incremental packet clearing #2167

adizere commented May 2, 2022 •

edited

Loading

lyqingye commented May 2, 2022 •

edited

Loading

lyqingye commented May 2, 2022 •

edited

Loading

adizere commented May 2, 2022

lyqingye commented May 2, 2022 •

edited

Loading

seanchen1991 May 2, 2022

romac May 3, 2022

adizere May 3, 2022

ancazamfir May 13, 2022

adizere May 13, 2022 •

edited

Loading

lyqingye commented May 4, 2022 •

edited

Loading

adizere commented May 4, 2022

ancazamfir left a comment •

edited

Loading

adizere commented May 12, 2022

ancazamfir left a comment •

edited

Loading

Support for incremental packet clearing #2167

Support for incremental packet clearing #2167

Conversation

adizere commented May 2, 2022 • edited Loading

Basic manual tests

Setup

Test with this branch

Test with master branch

PR author checklist:

Reviewer checklist:

lyqingye commented May 2, 2022 • edited Loading

lyqingye commented May 2, 2022 • edited Loading

adizere commented May 2, 2022

lyqingye commented May 2, 2022 • edited Loading

seanchen1991 May 2, 2022

Choose a reason for hiding this comment

romac May 3, 2022

Choose a reason for hiding this comment

adizere May 3, 2022

Choose a reason for hiding this comment

ancazamfir May 13, 2022

Choose a reason for hiding this comment

adizere May 13, 2022 • edited Loading

Choose a reason for hiding this comment

lyqingye commented May 4, 2022 • edited Loading

adizere commented May 4, 2022

ancazamfir left a comment • edited Loading

Choose a reason for hiding this comment

adizere commented May 12, 2022

ancazamfir left a comment • edited Loading

Choose a reason for hiding this comment

adizere commented May 2, 2022 •

edited

Loading

Test with `master` branch

lyqingye commented May 2, 2022 •

edited

Loading

lyqingye commented May 2, 2022 •

edited

Loading

lyqingye commented May 2, 2022 •

edited

Loading

adizere May 13, 2022 •

edited

Loading

lyqingye commented May 4, 2022 •

edited

Loading

ancazamfir left a comment •

edited

Loading

ancazamfir left a comment •

edited

Loading