Watch event was delayed — are there any known limitations on event delivery timing?

[jeonggoo]

Etcd version: 3.5.17
Number of etcd instances: 3

There was an instance in my system where an etcd watch was triggered approximately 50 seconds after a key was deleted. The etcd logs for both the leader and non-leader nodes showed no warnings or errors. I couldn’t find any official etcd documentation explaining limitations or guarantees regarding the timing of watch events. The system experiences a significant amount of traffic to the etcd cluster, using both gRPC unary and streaming APIs.

Here is a simplified overview of the system:

There are three processes in my deployment. All three are written in C++ and communicate with the etcd cluster via gRPC.

Setup

Process A

1. Creates a lease with TTL with 10 second
2. Puts a key/value entry with the lease created in the previous step (key: myPrefix_myKey, value: some_value)
3. Sends LeaseKeepAlive in every 2 seconds

Process B and C

1. Creates a watch stream
2. Creates a watch with prefix myPrefix

Test Setup

1. Kills process A forcefully
2. Confirms process B and C receives watch event with EventType::DELETE for the key myPrefix_myKey

The test have been run numerous time however there was once instance where both process B and C received the watch event around 50 seconds after a key deleted.

Is there a known issue or limitation on timing of watch event delivery?

[serathius]

Server your client was connected to got disconnected from the leader, so it and client stopped receiving updates. To mitigate it you normally would pass WithRequireLeader in Go. This forces member that gets disconnected from leader to drop the watch, forcing your client to reconnect to other member. You might need to implement it for your C++ library.

[jeonggoo]

@serathius Thanks for the metadata - I'll look into it further. Since the logs from all three etcd nodes show no leader loss, would the metadata set by WithRequiredLeader have had any effect?

• 06:41:03 Process A was killed at
• 06:42:07 Process B and C received watch event (EventType::DELETE)

The following log snippets were trimmed before and after the log entries, but no lines were removed from the first and last entries

[leader] ./etcd-cluster-vgw5q9r9ls_ffecebfd-f754-4815-aa70-b5c11f02324c/etcd/0.log

2025-07-15T06:30:58.95381863Z stderr F {"level":"info","ts":"2025-07-15T06:30:58.953628Z","caller":"mvcc/kvstore_compaction.go:72","msg":"finished scheduled compaction","compact-revision":279473,"took":"642.136002ms","hash":2998354524,"current-db-size-bytes":19591168,"current-db-size":"20 MB","current-db-size-in-use-bytes":14663680,"current-db-size-in-use":"15 MB"}
2025-07-15T06:30:58.953848636Z stderr F {"level":"info","ts":"2025-07-15T06:30:58.953702Z","caller":"mvcc/hash.go:151","msg":"storing new hash","hash":2998354524,"revision":279473,"compact-revision":278692}
2025-07-15T07:03:34.3116383Z stderr F {"level":"warn","ts":"2025-07-15T07:03:34.311209Z","caller":"etcdserver/raft.go:426","msg":"leader failed to send out heartbeat on time; took too long, leader is overloaded likely from slow disk","to":"a2fe8ed132e73da3","heartbeat-interval":"100ms","expected-duration":"200ms","exceeded-duration":"163.679334ms"}
2025-07-15T07:03:34.31168652Z stderr F {"level":"warn","ts":"2025-07-15T07:03:34.311301Z","caller":"etcdserver/raft.go:426","msg":"leader failed to send out heartbeat on time; took too long, leader is overloaded likely from slow disk","to":"67eea06bbd659fea","heartbeat-interval":"100ms","expected-duration":"200ms","exceeded-duration":"163.782997ms"}

[non-leader] ./etcd-cluster-zcsbrxvx5g_3e537e6a-ea25-4193-be24-830260f50a28/etcd/0.log

2025-07-15T06:30:58.285101978Z stderr F {"level":"info","ts":"2025-07-15T06:30:58.284938Z","caller":"mvcc/index.go:214","msg":"compact tree index","revision":279473}
2025-07-15T06:30:58.96632391Z stderr F {"level":"info","ts":"2025-07-15T06:30:58.966212Z","caller":"mvcc/kvstore_compaction.go:72","msg":"finished scheduled compaction","compact-revision":279473,"took":"652.500981ms","hash":2998354524,"current-db-size-bytes":19595264,"current-db-size":"20 MB","current-db-size-in-use-bytes":14667776,"current-db-size-in-use":"15 MB"}
2025-07-15T06:30:58.966342635Z stderr F {"level":"info","ts":"2025-07-15T06:30:58.966274Z","caller":"mvcc/hash.go:151","msg":"storing new hash","hash":2998354524,"revision":279473,"compact-revision":278692}
2025-07-15T06:55:00.306436236Z stderr F {"level":"info","ts":"2025-07-15T06:55:00.306265Z","caller":"traceutil/trace.go:171","msg":"trace[1001755517] linearizableReadLoop","detail":"{readStateIndex:444534; appliedIndex:444534; }","duration":"100.772664ms","start":"2025-07-15T06:55:00.205475Z","end":"2025-07-15T06:55:00.306248Z","steps":["trace[1001755517] 'read index received'  (duration: 100.768666ms)","trace[1001755517] 'applied index is now lower than readState.Index'  (duration: 3.056µs)"],"step_count":2}
2025-07-15T06:55:00.306552162Z stderr F {"level":"warn","ts":"2025-07-15T06:55:00.306479Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"100.987693ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/plat/cluster/raid/data/free_pool/7_\" range_end:\"/plat/cluster/raid/data/free_pool/7`\" limit:4294967295 sort_order:ASCEND ","response":"range_response_count:22 size:1265"}

[non-leader] ./etcd-cluster-vchx2bq5kx_8ac2dcb9-80e2-4ab7-af02-cee267b3850c/etcd/0.log

2025-07-15T06:30:59.206708579Z stderr F {"level":"info","ts":"2025-07-15T06:30:59.206560Z","caller":"mvcc/kvstore_compaction.go:72","msg":"finished scheduled compaction","compact-revision":279473,"took":"887.768869ms","hash":2998354524,"current-db-size-bytes":19603456,"current-db-size":"20 MB","current-db-size-in-use-bytes":14675968,"current-db-size-in-use":"15 MB"}
2025-07-15T06:30:59.20673038Z stderr F {"level":"info","ts":"2025-07-15T06:30:59.206630Z","caller":"mvcc/hash.go:151","msg":"storing new hash","hash":2998354524,"revision":279473,"compact-revision":278692}
2025-07-15T07:30:58.290554501Z stderr F {"level":"info","ts":"2025-07-15T07:30:58.290441Z","caller":"mvcc/index.go:214","msg":"compact tree index","revision":280297}
2025-07-15T07:30:59.001596507Z stderr F {"level":"info","ts":"2025-07-15T07:30:59.001485Z","caller":"mvcc/kvstore_compaction.go:72","msg":"finished scheduled compaction","compact-revision":280297,"took":"684.924167ms","hash":2967774786,"current-db-size-bytes":19603456,"current-db-size":"20 MB","current-db-size-in-use-bytes":15187968,"current-db-size-in-use":"15 MB"}
2025-07-15T07:30:59.001616855Z stderr F {"level":"info","ts":"2025-07-15T07:30:59.001529Z","caller":"mvcc/hash.go:151","msg":"storing new hash","hash":2967774786,"revision":280297,"compact-revision":279473}
2025-07-15T08:19:04.061362229Z stderr F {"level":"info","ts":"2025-07-15T08:19:04.060559Z","caller":"traceutil/trace.go:171","msg":"trace[306770988] linearizableReadLoop","detail":"{readStateIndex:450032; appliedIndex:450032; }","duration":"111.941897ms","start":"2025-07-15T08:19:03.948597Z","end":"2025-07-15T08:19:04.060539Z","steps":["trace[306770988] 'read index received'  (duration: 111.936477ms)","trace[306770988] 'applied index is now lower than readState.Index'  (duration: 4.178µs)"],"step_count":2}
2025-07-15T08:19:04.061398297Z stderr F {"level":"warn","ts":"2025-07-15T08:19:04.060839Z","caller":"etcdserver/util.go:170","msg":"apply request took too long","took":"112.222451ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/plat/cluster/raid/data/free_pool/4_\" range_end:\"/plat/cluster/raid/data/free_pool/4`\" limit:4294967295 sort_order:ASCEND ","response":"range_response_count:23 size:1324"}