Use application latest height in `query_status` #2021

ancazamfir · 2022-03-28T11:48:52Z

Closes: #1970

Description

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).

ancazamfir · 2022-04-04T12:14:37Z

relayer/src/chain/cosmos.rs

+ /// Query the application status
+ fn query_application_status(&self) -> Result<StatusResponse, Error> {
+ crate::time!("query_application_status");
+ crate::telemetry!(query, self.id(), "query_application_status");

- let status = self.status()?;
+ // query the chain status
+ let status = self.chain_status()?;
+
+ // query the application status
+ let abci_status = self
+ .block_on(self.rpc_client.abci_info())
+ .map_err(|e| Error::rpc(self.config.rpc_addr.clone(), e))?;
+
+ // has the application been updated with latest block?
+ let time = if abci_status.last_block_height == status.sync_info.latest_block_height {
+ // yes, use the chain latest block time
+ status.sync_info.latest_block_time
+ } else {
+ // no, retrieve the time of the header at application latest height
+ self.block_on(self.rpc_client.commit(abci_status.last_block_height))
+ .map_err(|e| Error::rpc(self.config.rpc_addr.clone(), e))?
+ .signed_header
+ .header
+ .time
+ };


This is the main change for this PR. It requires 3 RPCs instead of one. And this happens for handling of every IBC send packet event with impact on relayer performance and extra churn on the full node. So I am a bit hesitant to move this forward until performance tests are done and/or get all info in one RPC.
I opened tendermint/tendermint#8248 to get input from tendermint team.

I am also wary of increasing the pressure on the node, especially for every SendPacket event.

Are we seeing this only when issuing queries manually or is it also happening during relaying? If only the former, I would vote for waiting until we can get away with a single RPC call or until something like this is implemented.

This is seen during relaying and can cause failures for any query. In one extreme case reported by Mircea (see issue) hermes was not relaying at all on a channel as it was not able to spawn workers due to connection not found.
This was fixed with a partial fix, similar to the one in this PR but without the time fix (i.e. we would only fix the height to be the application height). When I did some tests with custom chains (with increased block execution times) the lack of time fix would sometime cause header in the future chain error for client updates.

adizere · 2022-04-22T10:46:03Z

I did some basic benchmarking with two RPC nodes:

ecostake: https://rpc-cosmoshub.ecostake.com/
pupmos: https://rpc.cosmoshub.pupmos.network

Both found from here: https://chain-registry.netlify.app

I looked at these 5 endpoints:

/status
/abci_info
/commit
/header?height=X
/blockchain?minHeight=X&maxHeight=X

These numbers are preliminary, and may not reflect other operator's endpoints performance.

Basic takeaway: If we can, we should avoid the /commit endpoint, which can be ~30% slower than the others. /abci_info can also be problematic.

Data

The numbers are in milliseconds.

	/status	/abci_info	/commit	/header	/blockchain
pupmos	108	105	134	101	106
ecostake	107	152	143	98	99

ancazamfir · 2022-04-23T02:07:42Z

I did some basic benchmarking with two RPC nodes:

Thanks @adizere for this! For some reason I don't see the header RPC. What is the exact command you used for this?

adizere · 2022-04-25T11:07:45Z

For some reason I don't see the header RPC. What is the exact command you used for this?

Good point. The header endpoint is still a draft PR in tendermint-rs: informalsystems/tendermint-rs#1101.
The data I extracted above was by querying via time curl http:$RPC/$ENDPOINT

adizere

We need to reproduce the problem reliably. I haven't yet checked Anca's instructions from here, but that's probably the best place to start from.

adizere · 2022-04-25T14:53:54Z

relayer/src/chain/cosmos.rs

+ let blocks = self
+ .block_on(
+ self.rpc_client
+ .blockchain(abci_info.last_block_height, abci_info.last_block_height),


Note to reviewers:

we query /blockchain?minHeight=last_block_height&maxHeight=last_block_height to fetch the metadata for a single block

adizere · 2022-04-25T14:55:16Z

relayer/src/chain/cosmos.rs


 // Check that transaction indexing is enabled
 if status.node_info.other.tx_index != TxIndexStatus::On {
 return Err(Error::tx_indexing_disabled(chain_id.clone()));
 }

+ // Check that the chain identifier matches the network name


Note: This change has not much to do with the present PR. It's just an additional non-critical health check that can reveal misconfigurations of config.toml.

romac · 2022-04-27T07:49:28Z

I believe I am still seeing the same issue, when running the script against Gaia v6.0.3 using a patched Tendermint:

Query Chain ID: ibc-0, Conn ID: connection-0, Height: 62, ABCI_Height: 61
2022-04-27T07:44:42.335551Z DEBUG ThreadId(01) Options: QueryConnectionEndCmd { chain_id: ChainId { id: "ibc-0", version: 0 }, connection_id: ConnectionId("connection-0"), height: Some(62) }
Error:
   0: connection not found: connection-0



Query Chain ID: ibc-0, Conn ID: connection-0, Height: 62, ABCI_Height: 62
2022-04-27T07:44:45.386849Z DEBUG ThreadId(01) Options: QueryConnectionEndCmd { chain_id: ChainId { id: "ibc-0", version: 0 }, connection_id: ConnectionId("connection-0"), height: Some(62) }
Success: ConnectionEnd {
    state: Open,
    client_id: ClientId(
        "07-tendermint-0",
    ),
    counterparty: Counterparty {
        client_id: ClientId(
            "07-tendermint-0",
        ),
        connection_id: Some(
            ConnectionId(
                "connection-0",
            ),
        ),
        prefix: ibc,
    },
    versions: [
        Version {
            identifier: "1",
            features: [
                "ORDER_ORDERED",
                "ORDER_UNORDERED",
            ],
        },
    ],
    delay_period: 0ns,
}

romac · 2022-04-27T08:51:23Z

Detailed instructions for reproducing the issue and results:

cd /tmp
mkdir gaia-test
cd gaia-test
git clone https://github.com/tendermint/tendermint
cd tendermint
git switch v0.34.14

apply

diff --git a/state/execution.go b/state/execution.go
index 2cc3db6e7..16f150702 100644
--- a/state/execution.go
+++ b/state/execution.go
@@ -323,6 +323,8 @@ func execBlockOnProxyApp(
        }
    }

+  time.Sleep(time.Millisecond * 500)
+
    // End block.
    abciResponses.EndBlock, err = proxyAppConn.EndBlockSync(abci.RequestEndBlock{Height: block.Height})
    if err != nil {

cd ..
git clone https://github.com/cosmos/gaia
cd gaia

apply

diff --git a/go.mod b/go.mod
index 7465a0be..e3a508c5 100644
--- a/go.mod
+++ b/go.mod
@@ -124,4 +124,5 @@ replace (
    github.com/cosmos/cosmos-sdk => github.com/cosmos/cosmos-sdk v0.44.2
    github.com/gogo/protobuf => github.com/regen-network/protobuf v1.3.3-alpha.regen.1
    google.golang.org/grpc => google.golang.org/grpc v1.33.2
+   github.com/tendermint/tendermint => /tmp/gaia-test/tendermint
 )

make build

vim ~/.gm/gm.toml

[global]
add_to_hermes        = false
auto_maintain_config = true
extra_wallets        = 0
gaiad_binary         = "/private/tmp/gaia-test/gaia/build/gaiad"
hdpath               = ""
home_dir             = "$HOME/.gm"
ports_start_at       = 27040

[global.hermes]
binary            = "$HOME/Informal/Code/Current/ibc-rs/target/debug/build/hermes"
config            = "$HOME/.hermes/config.toml"
log_level         = "info"
telemetry_enabled = true
telemetry_host    = "127.0.0.1"
telemetry_port    = 3001

[ibc-0]
ports_start_at = 27000
add_to_hermes  = true

[ibc-1]
ports_start_at = 27010
add_to_hermes  = true

gm reset
gm start
gm hermes config
remove filter = false from ~/.hermes/config.toml
Go to ibc-rs working directory
git fetch origin
git switch anca/app_latest_height
git pull
cargo build
gm hermes keys
cargo run -- create channel ibc-0 -c ibc-1 --port-a transfer --port-b transfer --new-client-connection

paste this in query_conn.sh

#!/bin/bash

addr=$1
chain=$2
conn=$3
for i in {1..100}
do
    read -r height < <(
        curl -s "$addr"/status | jq -r '.result.sync_info.latest_block_height')
    read -r abci_height < <(
        curl -s "$addr"/abci_info | jq -r '.result.response.last_block_height')
    echo "Query Chain ID: ${chain}, Conn ID: ${conn}, Height: ${height}, ABCI_Height: ${abci_height}"
    ./target/debug/hermes query connection end $chain $conn -H $height
    sleep 1
done

bash query_conn.sh 'http://localhost:27000' ibc-0 connection-0

adizere · 2022-04-27T09:43:49Z

Great instruction for testing Romain, thank you for sharing that!

I was able to see the same issue as you. E.g.:

Query Chain ID: ibc-0, Conn ID: connection-0, Height: 101, ABCI_Height: 100
2022-04-27T09:15:28.911674Z INFO ThreadId(01) using default configuration from '/Users/adi/.hermes/config.toml'
Error: connection not found: connection-0

After digging into it, I realize that hermes query connection end which we use in this query_conn.sh testing script does not invoke query_application_status, which is what this PR solves. So I think it would be expected that we encounter this problem when running query_conn.sh script.

To summarize, I think the purpose of query_conn.sh is to simulate the problem that Hermes encounters when querying with blockchain height (-H $height) instead of querying with application height (-H $abci_height). I don't understand how this problem relates to the original issue (#1970), however, because I don't see where exactly does Hermes rely on blockchain height in the supervisor or scan part as these logs show:

2022-03-03T19:40:34.805800Z ERROR ThreadId(01) skipped workers for connection connection-20 on chain gravity-bridge-3, reason: relayer error: connection not found: connection-464
2022-03-03T19:40:34.805834Z INFO ThreadId(01) channel channel-17 on chain gravity-bridge-3 is: OPEN; state on dest. chain (cosmoshub-4) is: UNINITIALIZED

That being said, this PR only replaces the use of blockchain height with application height specifically for query_application_status. I'm not convinced this is enough to solve the error reported in the issue (#1970).

ancazamfir · 2022-04-27T11:57:14Z

The script retrieves the blockchain height then queries the connection with that height. If the height is higher than the application query state height you see that error. I used this script because in the original issue the command used was query channel ends which queries the connection with the blockchain latest height.
Also in hermes we sometimes query the latest height and then we do subsequent queries and gather proofs with that fixed height.
You can try to run tests (e.g. e2e) from master with the repro setup and you will see quite a few failures.

romac · 2022-04-28T12:03:42Z

You can try to run tests (e.g. e2e) from master with the repro setup and you will see quite a few failures.

Alright so I've done just that a couple times, both against master and against this branch, and I did indeed see a bunch of errors with master when querying channel and connection ends but not a single one with this branch 🎉

To me this is good to merge :)

adizere

Thank you Anca for kicking off the fix and your guidance! Amazing work Romain with testing! LGTM 🚀

* Test with abci_status * Fix status also * Remove redundant code * Move changes in chain query_application_status() * Cargo fmt * Added /blockchain-based implementation for query_application_status * Documenting impl of query_application_status. * changelog * Cleanup Co-authored-by: Adi Seredinschi <adi@informal.systems>

ancazamfir added 4 commits March 4, 2022 15:46

Test with abci_status

8af44a7

Merge branch 'master' into anca/app_latest_height

839a9cb

Fix status also

183a97b

Remove redundant code

b0df701

ancazamfir changed the title ~~Anca/app latest height~~ Use application latest height in query_status Mar 28, 2022

Move changes in chain query_application_status()

0294c63

ancazamfir commented Apr 4, 2022

View reviewed changes

ancazamfir added 2 commits April 21, 2022 08:48

Merge branch 'master' into anca/app_latest_height

e22e8bb

Cargo fmt

f530303

adizere added the P-high label Apr 25, 2022

adizere added 3 commits April 25, 2022 14:41

Added /blockchain-based implementation for query_application_status

e17d0b3

Documenting impl of query_application_status.

17db344

changelog

dde5ece

adizere marked this pull request as ready for review April 25, 2022 14:51

adizere self-requested a review as a code owner April 25, 2022 14:51

Cleanup

b34f96b

adizere reviewed Apr 25, 2022

View reviewed changes

adizere assigned romac and adizere Apr 26, 2022

adizere removed the P-high label Apr 27, 2022

adizere assigned ancazamfir Apr 27, 2022

adizere approved these changes Apr 28, 2022

View reviewed changes

adizere merged commit cb33212 into master Apr 28, 2022

adizere deleted the anca/app_latest_height branch April 28, 2022 15:10

rhuairahrighairidh mentioned this pull request May 5, 2022

Client Ugrade Command Not Working in v0.14.1 #2185

Closed

5 tasks

romac mentioned this pull request Jul 20, 2022

Unable to relay packets with error (serde parse error: missing field data) #2444

Closed

5 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Use application latest height in `query_status` #2021

Use application latest height in `query_status` #2021

ancazamfir commented Mar 28, 2022 •

edited by adizere

Loading

ancazamfir Apr 4, 2022

romac Apr 5, 2022

ancazamfir Apr 6, 2022

adizere commented Apr 22, 2022

ancazamfir commented Apr 23, 2022 •

edited

Loading

adizere commented Apr 25, 2022

adizere left a comment

adizere Apr 25, 2022

adizere Apr 25, 2022 •

edited

Loading

romac commented Apr 27, 2022

romac commented Apr 27, 2022 •

edited

Loading

adizere commented Apr 27, 2022

ancazamfir commented Apr 27, 2022

romac commented Apr 28, 2022

adizere left a comment

Use application latest height in query_status #2021

Use application latest height in query_status #2021

Conversation

ancazamfir commented Mar 28, 2022 • edited by adizere Loading

Description

PR author checklist:

Reviewer checklist:

ancazamfir Apr 4, 2022

Choose a reason for hiding this comment

romac Apr 5, 2022

Choose a reason for hiding this comment

ancazamfir Apr 6, 2022

Choose a reason for hiding this comment

adizere commented Apr 22, 2022

ancazamfir commented Apr 23, 2022 • edited Loading

adizere commented Apr 25, 2022

adizere left a comment

Choose a reason for hiding this comment

adizere Apr 25, 2022

Choose a reason for hiding this comment

adizere Apr 25, 2022 • edited Loading

Choose a reason for hiding this comment

romac commented Apr 27, 2022

romac commented Apr 27, 2022 • edited Loading

adizere commented Apr 27, 2022

ancazamfir commented Apr 27, 2022

romac commented Apr 28, 2022

adizere left a comment

Choose a reason for hiding this comment

Use application latest height in `query_status` #2021

Use application latest height in `query_status` #2021

ancazamfir commented Mar 28, 2022 •

edited by adizere

Loading

ancazamfir commented Apr 23, 2022 •

edited

Loading

adizere Apr 25, 2022 •

edited

Loading

romac commented Apr 27, 2022 •

edited

Loading