Packet timeout timestamp at IBC is not updated until next TX

[RaulBernal]

Summary of Bug

The field value timeout_timestamp is not recalculated properly.
Until a new valid TX is generated, the value of the field is not recalculated.
This causes invalid packets if a valid TX is not sent within 10 minutes (default value of the timeout).

Version

From SDK v.0.42.x to v.0.44.x
Tested in

• Osmosis v.4.1.0 cosmos_sdk_version: v0.42.9
• BitCanna v.1.2 cosmos sdk_version: v.0.44.2

Steps to Reproduce

$date
Mon Oct 25 08:00:40 UTC 2021
$ bcnad tx ibc-transfer transfer transfer channel-1 osmo1skyy4yhejshhs9rv67fl2dswnlhk3mfugvr7sv 69ubcna  --gas auto --gas-prices 0.001ubcna --gas-adjustment 1.5  --from validator  --packet-timeout-timestamp 600000000000
Enter keyring passphrase:
gas estimate: 102783
{"body":{"messages":[{"@type":"/ibc.applications.transfer.v1.MsgTransfer","source_port":"transfer","source_channel":"channel-1","token":{"denom":"ubcna","amount":"69"},"sender":"bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af","receiver":"osmo1skyy4yhejshhs9rv67fl2dswnlhk3mfugvr7sv","timeout_height":{"revision_number":"1","revision_height":"1724774"},"timeout_timestamp":"1635148912350984020"}],"memo":"","timeout_height":"0","extension_options":[],"non_critical_extension_options":[]},"auth_info":{"signer_infos":[],"fee":{"amount":[{"denom":"ubcna","amount":"103"}],"gas_limit":"102783","payer":"","granter":""}},"signatures":[]}

confirm transaction before signing and broadcasting [y/N]: n
cancelled transaction
$ date
Mon Oct 25 08:01:04 UTC 2021
$ bcnad tx ibc-transfer transfer transfer channel-1 osmo1skyy4yhejshhs9rv67fl2dswnlhk3mfugvr7sv 69ubcna  --gas auto --gas-prices 0.001ubcna --gas-adjustment 1.5  --from validator  --packet-timeout-timestamp 600000000000
Enter keyring passphrase:
gas estimate: 102783
{"body":{"messages":[{"@type":"/ibc.applications.transfer.v1.MsgTransfer","source_port":"transfer","source_channel":"channel-1","token":{"denom":"ubcna","amount":"69"},"sender":"bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af","receiver":"osmo1skyy4yhejshhs9rv67fl2dswnlhk3mfugvr7sv","timeout_height":{"revision_number":"1","revision_height":"1724774"},"timeout_timestamp":"1635148912350984020"}],"memo":"","timeout_height":"0","extension_options":[],"non_critical_extension_options":[]},"auth_info":{"signer_infos":[],"fee":{"amount":[{"denom":"ubcna","amount":"103"}],"gas_limit":"102783","payer":"","granter":""}},"signatures":[]}

confirm transaction before signing and broadcasting [y/N]: n

We get this error on relayer:
I[2021-10-25|08:02:09.671] ✘ [osmosis-1]@{1723868} - msg(0:/ibc.core.client.v1.MsgUpdateClient,1:/ibc.core.channel.v1.MsgRecvPacket) err(channel:14:failed to execute message; message index: 1: receive packet verification failed: block timestamp >= packet timeout timestamp (2021-10-25 08:02:00.472031016 +0000 UTC >= 2021-10-25 08:01:52.35098402 +0000 UTC): packet timeout)

The same for osmosisd

$ osmosisd tx ibc-transfer transfer transfer channel-51 bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af 1uosmo --from test
Enter keyring passphrase:
{"body":{"messages":[{"@type":"/ibc.applications.transfer.v1.MsgTransfer","source_port":"transfer","source_channel":"channel-51","token":{"denom":"uosmo","amount":"1"},"sender":"osmo1skyy4yhejshhs9rv67fl2dswnlhk3mfugvr7sv","receiver":"bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af","timeout_height":{"revision_number":"1","revision_height":"371458"},"timeout_timestamp":"1635148630217372060"}],"memo":"","timeout_height":"0","extension_options":[],"non_critical_extension_options":[]},"auth_info":{"signer_infos":[],"fee":{"amount":[],"gas_limit":"200000","payer":"","granter":""}},"signatures":[]}

confirm transaction before signing and broadcasting [y/N]: n
cancelled transaction

$ osmosisd tx ibc-transfer transfer transfer channel-51 bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af 1uosmo --from test
Enter keyring passphrase:
{"body":{"messages":[{"@type":"/ibc.applications.transfer.v1.MsgTransfer","source_port":"transfer","source_channel":"channel-51","token":{"denom":"uosmo","amount":"1"},"sender":"osmo1skyy4yhejshhs9rv67fl2dswnlhk3mfugvr7sv","receiver":"bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af","timeout_height":{"revision_number":"1","revision_height":"371458"},"timeout_timestamp":"1635148630217372060"}],"memo":"","timeout_height":"0","extension_options":[],"non_critical_extension_options":[]},"auth_info":{"signer_infos":[],"fee":{"amount":[],"gas_limit":"200000","payer":"","granter":""}},"signatures":[]}

confirm transaction before signing and broadcasting [y/N]: n
cancelled transaction
$ osmosisd tx ibc-transfer transfer transfer channel-51 bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af 1uosmo --from test
Enter keyring passphrase:
incorrect passphrase
Enter keyring passphrase:
{"body":{"messages":[{"@type":"/ibc.applications.transfer.v1.MsgTransfer","source_port":"transfer","source_channel":"channel-51","token":{"denom":"uosmo","amount":"1"},"sender":"osmo1skyy4yhejshhs9rv67fl2dswnlhk3mfugvr7sv","receiver":"bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af","timeout_height":{"revision_number":"1","revision_height":"371458"},"timeout_timestamp":"1635148630217372060"}],"memo":"","timeout_height":"0","extension_options":[],"non_critical_extension_options":[]},"auth_info":{"signer_infos":[],"fee":{"amount":[],"gas_limit":"200000","payer":"","granter":""}},"signatures":[]}

confirm transaction before signing and broadcasting [y/N]: y

The TX timeout value was 14 minutes in the past
E[2021-10-25|08:12:10.254] - [bitcanna-1] -> err(rpc error: code = InvalidArgument desc = failed to execute message; message index: 1: receive packet verification failed: block timestamp >= packet timeout timestamp (2021-10-25 08:12:03.465933869 +0000 UTC >= 2021-10-25 07:57:10.21737206 +0000 UTC): packet timeout: invalid request)

---

For Admin Use

• Not duplicate issue
• Appropriate labels applied
• Appropriate contributors tagged
• Contributor assigned/self-assigned

[RaulBernal]

I'm relaying with go-relayer at this moment, but also happens with Hermes and with TS relayer.. The timeout recalculate issue happens before I send the TX, if you see the logs you can get the wrong timeout (I canceled the TX and tested with another) El lun., 25 oct. 2021 16:43, Anca Zamfir ***@***.***> escribió:

…

Please include the hermes config and version that you are using. Also the sequence of operations, specifically are you running hermes before you send the transfers? Or you do hermes start after? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#10429 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AA4T75TX2OXVXUAUN6ANEJDUIVUHPANCNFSM5GUX7N4Q> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

[jtieri]

Similar issue is opened here informalsystems/hermes#1445 as well as cosmos/ibc-go#492

[RaulBernal]

Yes, I saw this logs about the future. In this case when you have a chain with few TX by hour, you experiment the timeouts. The way to avoid for me is to setup a script that raise a TX before the 10minutes (default timeout) El lun., 25 oct. 2021 18:28, Justin Tieri ***@***.***> escribió:

…

Similar issue is opened here informalsystems/hermes#1445 <informalsystems/hermes#1445> as well as cosmos/ibc-go#492 <cosmos/ibc-go#492> — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#10429 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AA4T75WBZ2XWJ7PLKZVWS73UIWARLANCNFSM5GUX7N4Q> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

[ancazamfir]

It is possible for a packet to not be timed out when evaluated but the timeout to pass by the it is processed by the chain. In hermes the error should trigger a retry and at that time a timeout should be sent.

This causes invalid packets if a valid TX is not sent within 10 minutes (default value of the timeout).

We are not aware of this. Could you please open an issue in ibc-rs and provide the block times of the two chains, hermes config.toml you are using, version and operation order. Specifically, do you send the packets and then start hermes? Or is hermes already started?

I also noticed that the packet timeout stamp is 2021-10-25 08:01:52.35098402 +0000 UTC while the packet seems to have been sent at 08:00:40 UTC 2021 which looks like a smaller timeout.

[RaulBernal]

I will open a issue at ibc-go. I'm using GoRelayer(last version of Strange Ventures) but I'm suffering this error from months ago in all the working relayers (go, TS, hermes) because if you simulate the TX you can see how the timestamp is the same even when you wait for a minutes before try it again, see the logs in the first post. When we use hermes, of course is running in background as service, and after passing the initial checkings. El lun., 25 oct. 2021 18:58, Anca Zamfir ***@***.***> escribió:

…

It is possible for a packet to not be timed out when evaluated but the timeout to pass by the it is processed by the chain. In hermes the error should trigger a retry and at that time a timeout should be sent. This causes invalid packets if a valid TX is not sent within 10 minutes (default value of the timeout). We are not aware of this. Could you please open an issue in ibc-rs <https://github.com/informalsystems/ibc-rs/> and provide the block times of the two chains, hermes config.toml you are using, version and operation order. Specifically, do you send the packets and then start hermes? Or is hermes already started? I also noticed that the packet timeout stamp is 2021-10-25 08:01:52.35098402 +0000 UTC while the packet seems to have been sent at 08:00:40 UTC 2021 which looks like a smaller timeout. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#10429 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AA4T75WSK3YCM7KAWVZVLR3UIWEB5ANCNFSM5GUX7N4Q> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

[RaulBernal]

$ osmosisd tx ibc-transfer transfer transfer channel-51 bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af 1uosmo --from test
Enter keyring passphrase:
{"body":{"messages":[{"@type":"/ibc.applications.transfer.v1.MsgTransfer","source_port":"transfer","source_channel":"channel-51","token":{"denom":"uosmo","amount":"1"},"sender":"osmo1skyy4yhejshhs9rv67fl2dswnlhk3mfugvr7sv","receiver":"bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af","timeout_height":{"revision_number":"1","revision_height":"371458"},"timeout_timestamp":"1635148630217372060"}],"memo":"","timeout_height":"0","extension_options":[],"non_critical_extension_options":[]},"auth_info":{"signer_infos":[],"fee":{"amount":[],"gas_limit":"200000","payer":"","granter":""}},"signatures":[]}

confirm transaction before signing and broadcasting [y/N]: n
cancelled transaction

$ osmosisd tx ibc-transfer transfer transfer channel-51 bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af 1uosmo --from test
Enter keyring passphrase:
{"body":{"messages":[{"@type":"/ibc.applications.transfer.v1.MsgTransfer","source_port":"transfer","source_channel":"channel-51","token":{"denom":"uosmo","amount":"1"},"sender":"osmo1skyy4yhejshhs9rv67fl2dswnlhk3mfugvr7sv","receiver":"bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af","timeout_height":{"revision_number":"1","revision_height":"371458"},"timeout_timestamp":"1635148630217372060"}],"memo":"","timeout_height":"0","extension_options":[],"non_critical_extension_options":[]},"auth_info":{"signer_infos":[],"fee":{"amount":[],"gas_limit":"200000","payer":"","granter":""}},"signatures":[]}

confirm transaction before signing and broadcasting [y/N]: n
cancelled transaction
$ osmosisd tx ibc-transfer transfer transfer channel-51 bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af 1uosmo --from test
Enter keyring passphrase:
incorrect passphrase
Enter keyring passphrase:
{"body":{"messages":[{"@type":"/ibc.applications.transfer.v1.MsgTransfer","source_port":"transfer","source_channel":"channel-51","token":{"denom":"uosmo","amount":"1"},"sender":"osmo1skyy4yhejshhs9rv67fl2dswnlhk3mfugvr7sv","receiver":"bcna1606cfyw6q60umn9zvv5j77ds896r5wqsajy0af","timeout_height":{"revision_number":"1","revision_height":"371458"},"timeout_timestamp":"1635148630217372060"}],"memo":"","timeout_height":"0","extension_options":[],"non_critical_extension_options":[]},"auth_info":{"signer_infos":[],"fee":{"amount":[],"gas_limit":"200000","payer":"","granter":""}},"signatures":[]}

confirm transaction before signing and broadcasting [y/N]: y

Only trying the command and canceling the broadcasting you can see that timestamp is always the same,

So, not a relayer issue, I guess

[RaulBernal]

Opened an issue at IBC repo:
cosmos/ibc#611