Failed packet verification: packet-specified delay period has not been reached

[lyqingye]

Crate

hermes

Summary of Bug

error logs: 

2022-02-13T19:38:23.630978Z  INFO ThreadId(23) [chain:port/channel-0 -> target] clearing pending packets height=Some(Height { revision: 0, height: 1435559 })
2022-02-13T19:38:24.052961Z  INFO ThreadId(23) [chain:port/channel-0 -> target] found unprocessed SendPacket events for [Sequence(25246)] (first 10 shown here; total=1)
2022-02-13T19:38:24.052984Z  INFO ThreadId(23) [chain:port/channel-0 -> target] generate messages from batch with 1 events
2022-02-13T19:38:24.062747Z  INFO ThreadId(23) [chain:port/channel-0 -> target] scheduling op. data with 1 msg(s) for Destination (height 0-1435560)
2022-02-13T19:38:24.875063Z  INFO ThreadId(23) [chain:port/channel-0 -> target] finished scheduling pending packets clearing height=Some(Height { revision: 0, height: 1435559 })
2022-02-13T19:38:25.062889Z  INFO ThreadId(23) [chain:port/channel-0 -> target] relay op. data of 1 msgs(s) to Destination (height 0-1435560), delayed by: 1.00012235s [try 1/5]
2022-02-13T19:38:25.062913Z  INFO ThreadId(23) [chain:port/channel-0 -> target] prepending Destination client update @ height 0-1435560
2022-02-13T19:38:25.102220Z  INFO ThreadId(23) [chain:port/channel-0 -> target] assembled batch of 2 message(s)
2022-02-13T19:38:25.109056Z ERROR ThreadId(12) [target] estimate_gas: failed to simulate tx. propagating error to caller: 
gRPC call failed with status: status: Unknown, 
message: "failed to execute message; message index: 1: 
receive packet verification failed: couldn't verify counterparty packet commitment: failed packet commitment verification for client (07-tendermint-0): cannot verify packet until time: 1644781101580283164, current time: 1644781099180419908: packet-specified delay period has not been reached", 
details: [], metadata: MetadataMap { headers: {"content-type": "application/grpc", "x-cosmos-block-height": "891340"} }

log analysis:

1. latest height = 1435560, clearing pending packet height = latest height - 1 = 1435559
2. query unprocessed events at height = 1435559
3. build packet proof at height = 1435559
4. build update client at height = 1435560

There seems to be no problem with the logic. Proof height + 1 = client state height < latest height
But the error log looks strange

validTime = 1644781101580283164
currentTimestamp = 1644781099180419908
currentTimestamp < validTime

UpdateclientMsg and RecvPacketMsg are executed in the same transaction. under normal circumstances(delayTimePeriod = 0), ProcessedTime should be equal to CurrentTimestamp

delayTimePeriod = 0ns

func verifyDelayPeriodPassed(ctx sdk.Context, store sdk.KVStore, proofHeight exported.Height, delayTimePeriod, delayBlockPeriod uint64) error {
	// check that executing chain's timestamp has passed consensusState's processed time + delay time period
	processedTime, ok := GetProcessedTime(store, proofHeight)
	if !ok {
		return sdkerrors.Wrapf(ErrProcessedTimeNotFound, "processed time not found for height: %s", proofHeight)
	}
	currentTimestamp := uint64(ctx.BlockTime().UnixNano())
	validTime := processedTime + delayTimePeriod
	// NOTE: delay time period is inclusive, so if currentTimestamp is validTime, then we return no error
	if currentTimestamp < validTime {
		return sdkerrors.Wrapf(ErrDelayPeriodNotPassed, "cannot verify packet until time: %d, current time: %d",
			validTime, currentTimestamp)
	}
......

Version

0.10.0

Steps to Reproduce

unable to reproduce

Acceptance Criteria

---

For Admin Use

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

[adizere]

Related to #1772

[hu55a1n1]

Hi @lyqingye, we plan to test the connection delay feature more extensively as part of #1836. This issue might be related to #1772 (as Adi noted), but can you describe the expected behaviour in more detail here (not sure I understand what is wrong with that log entry)? Also, do you know if this connection has a non-zero delay_period?

[lyqingye]

Hi @lyqingye, we plan to test the connection delay feature more extensively as part of #1836. This issue might be related to #1772 (as Adi noted), but can you describe the expected behaviour in more detail here (not sure I understand what is wrong with that log entry)? Also, do you know if this connection has a non-zero delay_period?

I don't know why such an error log appears (it won't happen under normal circumstances). Please wait for me to provide more detailed trace log

delay_period = 0ns, so i think this issue not related to #1772

[ancazamfir]

delay_period = 0ns, so i think this issue not related to #1772

agreed. What versions of ibc-go/sdk are the chains you tested with?

[lyqingye]

delay_period = 0ns, so i think this issue not related to #1772

agreed. What versions of ibc-go/sdk are the chains you tested with?

ibc-go: v3.0.0

[adizere]

delay_period = 0ns, so i think this issue not related to #1772

agreed. What versions of ibc-go/sdk are the chains you tested with?

Any thoughts on what may be causing this verification error to occur?