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)

The way to avoid for me is to setup a script that raise a TX before the
10minutes (default timeout).

Other way to avoid is make the TX (even after of 10 minutes) with flag: --packet-timeout-timestamp 0 to disable the timeout function.

They Steps to reproduce are easy, don't need to send a TX, you can prepare but cancel the sending, so it don't touch the relayer:

$ 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

[crodriguezvega]

Thanks for reporting this issue, @RaulBernal.

First of all let me say that I don't have a solution yet, but I was trying to reproduce the issue yesterday and I would like to document here what I have seen.

I am running locally two chains (chain-1 and chain-2; using the simd binary in ibc-go branch release/v1.2.x) and hermes (v0.7.1).

I create a client, connection and channel between chain-1 and chain-2, and afterwards I query the client state of the counter party chain (chain-2) on chain-1:

Success: ClientState {
    chain_id: ChainId {
        id: "chain-2",
        version: 2,
    },
    trust_level: TrustThreshold {
        numerator: 1,
        denominator: 3,
    },
    trusting_period: 1209600s,
    unbonding_period: 1814400s,
    max_clock_drift: 5s,
    frozen_height: Height {
        revision: 0,
        height: 0,
    },
    latest_height: Height {
        revision: 2,
        height: 23,
    },
    upgrade_path: [
        "upgrade",
        "upgradedIBCState",
    ],
    allow_update: AllowUpdate {
        after_expiry: true,
        after_misbehaviour: true,
    },
}

So the light client representing chain-2 on chain-1 is updated with the consensus state at height 23.

I send (at approx. Wed Oct 27 2021 09:54:30 CEST) 5token from an account in chain-1 to an account chain-2 with a timeout of 10 minutes. This is the cli command:

./simd tx ibc-transfer transfer transfer channel-0 cosmos17dtl0mjt3t77kpuhg2edqzjpszulwhgzuj9ljs 5token 
--from cosmos1mjk79fjjgpplak5wq838w0yd982gzkyfrk07am 
--packet-timeout-timestamp 600000000000 
--keyring-backend test 
--home ../simtesting/chain1

and the message:

{
  "body": {
    "messages": [
      {
        "@type": "/ibc.applications.transfer.v1.MsgTransfer",
        "source_port": "transfer",
        "source_channel": "channel-0",
        "token": {
          "denom": "token",
          "amount": "5"
        },
        "sender": "cosmos1mjk79fjjgpplak5wq838w0yd982gzkyfrk07am",
        "receiver": "cosmos17dtl0mjt3t77kpuhg2edqzjpszulwhgzuj9ljs",
        "timeout_height": {
          "revision_number": "2",
          "revision_height": "1023"
        },
        "timeout_timestamp": "1635321817061875000"
      }
    ],
    "memo": "",
    "timeout_height": "0",
    "extension_options": [],
    "non_critical_extension_options": []
  },
  "auth_info": {
    "signer_infos": [],
    "fee": {
      "amount": [],
      "gas_limit": "200000",
      "payer": "",
      "granter": ""
    }
  },
  "signatures": []
}

The timeout_timestamp is 1635321817061875000 (Wed Oct 27 2021 10:03:37.061 AM CEST).

Transaction goes through. I check the balances of the sending account:

- amount: "99999241"
  denom: stake
- amount: "9995"
  denom: token
pagination:
  next_key: null
  total: "0"

and the receiving account:

- amount: "5"
  denom: ibc/B5CB286F69D48B2C4F6F8D8CF59011C40590DCF8A91617A5FBA9FF0A7B21307F
- amount: "99999097"
  denom: stake
- amount: "10000"
  denom: token
pagination:
  next_key: null
  total: "0"

Both balances look good.

I query the client state of the counter party chain (chain-2) on chain-1:

Success: ClientState {
    chain_id: ChainId {
        id: "chain-2",
        version: 2,
    },
    trust_level: TrustThreshold {
        numerator: 1,
        denominator: 3,
    },
    trusting_period: 1209600s,
    unbonding_period: 1814400s,
    max_clock_drift: 5s,
    frozen_height: Height {
        revision: 0,
        height: 0,
    },
    latest_height: Height {
        revision: 2,
        height: 104,
    },
    upgrade_path: [
        "upgrade",
        "upgradedIBCState",
    ],
    allow_update: AllowUpdate {
        after_expiry: true,
        after_misbehaviour: true,
    },
}

The light client representing chain-2 on chain-1 is now updated with the consensus state at height 104. So the hermes relayer has executed an update of the light client.

I wait more that 10 minutes and I try to send another 5token from an account in chain-1 to an account in chain-2 with a timeout of 10 minutes. This is the message:

{
  "body": {
    "messages": [
      {
        "@type": "/ibc.applications.transfer.v1.MsgTransfer",
        "source_port": "transfer",
        "source_channel": "channel-0",
        "token": {
          "denom": "token",
          "amount": "5"
        },
        "sender": "cosmos1mjk79fjjgpplak5wq838w0yd982gzkyfrk07am",
        "receiver": "cosmos17dtl0mjt3t77kpuhg2edqzjpszulwhgzuj9ljs",
        "timeout_height": {
          "revision_number": "2",
          "revision_height": "1104"
        },
        "timeout_timestamp": "1635321904764272000"
      }
    ],
    "memo": "",
    "timeout_height": "0",
    "extension_options": [],
    "non_critical_extension_options": []
  },
  "auth_info": {
    "signer_infos": [],
    "fee": {
      "amount": [],
      "gas_limit": "200000",
      "payer": "",
      "granter": ""
    }
  },
  "signatures": []
}

The timeout_timestamp is 1635321904764272000 (Wed Oct 27 2021 10:05:04.764 AM CEST), which it's based on the time when the light client in chain-1 was updated (at 09:55 AM CEST) during the first transfer. This is the logging from hermes:

Oct 27 09:55:05.998 DEBUG [chain-2 -> chain-1:07-tendermint-0] MsgUpdateAnyClient from trusted height 2-23 to target height 2-104

This second transfer fails. This is the logging from hermes:

Oct 27 10:09:26.337 DEBUG [chain-1:transfer/channel-0 -> chain-2] chain-1 => SendPacketEv(SendPacket - h:1-899, seq:2, path:channel-0/transfer->channel-0/transfer, toh:2-1104, tos:Timestamp(2021-10-27T08:05:04.764272+00:00)))
Oct 27 10:09:26.341 TRACE [chain-1:transfer/channel-0 -> chain-2] built timeout msg seq:2, path:channel-0/transfer->channel-0/transfer, toh:2-1104, tos:Timestamp(2021-10-27T08:05:04.764272+00:00)), proofs at height 2-893
Oct 27 10:09:26.341 DEBUG [chain-1:transfer/channel-0 -> chain-2] chain-1 <= /ibc.core.channel.v1.MsgTimeout from SendPacketEv(SendPacket - h:1-899, seq:2, path:channel-0/transfer->channel-0/transfer, toh:2-1104, tos:Timestamp(2021-10-27T08:05:04.764272+00:00)))

But I also see that hermes updates the light client in chain-1 from height 104 to 893:

Oct 27 10:09:26.467 DEBUG [chain-2 -> chain-1:07-tendermint-0] MsgUpdateAnyClient from trusted height 2-104 to target height 2-893

I can confirm that when I query the state:

Success: ClientState {
    chain_id: ChainId {
        id: "chain-2",
        version: 2,
    },
    trust_level: TrustThreshold {
        numerator: 1,
        denominator: 3,
    },
    trusting_period: 1209600s,
    unbonding_period: 1814400s,
    max_clock_drift: 5s,
    frozen_height: Height {
        revision: 0,
        height: 0,
    },
    latest_height: Height {
        revision: 2,
        height: 893,
    },
    upgrade_path: [
        "upgrade",
        "upgradedIBCState",
    ],
    allow_update: AllowUpdate {
        after_expiry: true,
        after_misbehaviour: true,
    },
}

So a couple of minutes later I try now again the transfer:

{
  "body": {
    "messages": [
      {
        "@type": "/ibc.applications.transfer.v1.MsgTransfer",
        "source_port": "transfer",
        "source_channel": "channel-0",
        "token": {
          "denom": "token",
          "amount": "5"
        },
        "sender": "cosmos1mjk79fjjgpplak5wq838w0yd982gzkyfrk07am",
        "receiver": "cosmos17dtl0mjt3t77kpuhg2edqzjpszulwhgzuj9ljs",
        "timeout_height": {
          "revision_number": "2",
          "revision_height": "1893"
        },
        "timeout_timestamp": "1635322765292576000"
      }
    ],
    "memo": "",
    "timeout_height": "0",
    "extension_options": [],
    "non_critical_extension_options": []
  },
  "auth_info": {
    "signer_infos": [],
    "fee": {
      "amount": [],
      "gas_limit": "200000",
      "payer": "",
      "granter": ""
    }
  },
  "signatures": []
}

The timeout_timestamp is 1635322765292576000 (Wed Oct 27 2021 10:19:25.292 AM CEST), which makes sense according to the time when the light client was updated. This transfer succeeds:

Oct 27 10:12:54.377 DEBUG [chain-1:transfer/channel-0 -> chain-2] chain-1 => SendPacketEv(SendPacket - h:1-1092, seq:3, path:channel-0/transfer->channel-0/transfer, toh:2-1893, tos:Timestamp(2021-10-27T08:19:25.292576+00:00)))
Oct 27 10:12:54.382 TRACE [chain-1:transfer/channel-0 -> chain-2] built recv_packet msg seq:3, path:channel-0/transfer->channel-0/transfer, toh:2-1893, tos:Timestamp(2021-10-27T08:19:25.292576+00:00)), proofs at height 1-1093
Oct 27 10:12:54.382 DEBUG [chain-1:transfer/channel-0 -> chain-2] chain-2 <= /ibc.core.channel.v1.MsgRecvPacket from SendPacketEv(SendPacket - h:1-1092, seq:3, path:channel-0/transfer->channel-0/transfer, toh:2-1893, tos:Timestamp(2021-10-27T08:19:25.292576+00:00)))

The balances also confirm that the transfer went through:

- amount: "99998977"
  denom: stake
- amount: "9990"
  denom: token
pagination:
  next_key: null
  total: "0"

- amount: "10"
  denom: ibc/B5CB286F69D48B2C4F6F8D8CF59011C40590DCF8A91617A5FBA9FF0A7B21307F
- amount: "99998940"
  denom: stake
- amount: "10000"
  denom: token
pagination:
  next_key: null
  total: "0"

In conclusion: I see the behavior that @RaulBernal reports that the timeout_timestamp of the transfer message might be in the past if the value of packet-timeout-timestamp is smaller than the time that have passed since the light client of the counter party chain has been updated. If that happens, then indeed the transfer fails; but what I see is that the light client should be updated and if the transfer is retried then it should succeed.

The timeout_timestamp is calculated based on the timestamp of the consensus state for the counter party chain:

https://github.com/cosmos/ibc-go/blob/main/modules/apps/transfer/client/cli/tx.go#L92

So if the consensus state has not been updated for a while and the packet-timeout-timestamp is such that (timestamp_consensus_state_light_client + packet-timeout-timestamp) < current_time, then the timeout_timestamp will be in the past and the message will immediately timeout.

cc @AdityaSripal @colin-axner @ancazamfir to kindly ask for their thoughts/ideas.

[crodriguezvega]

We had a team discussion and we decided to solve this by replacing consensusState.GetTimestamp() here with time.Now().UnixNano(). Assuming that the timeout delta (10 minutes by default) is not too short, then even if the clock of the counterparty chain drifts a bit from the clock of the sending chain, the transfer should still be accepted.

This issue affects only the CLI, so transfers done with the relayer commands or via wallets are not affected.

[crodriguezvega]

The fix for this is now released as part of v2.0.1. cc @RaulBernal