Watch on future revision might receive old events or notifications, happens when client connects to multiple members.

[serathius]

Bug report criteria

• This bug report is not security related, security issues should be disclosed privately via security@etcd.io.
• This is not a support request or question, support requests or questions should be raised in the etcd discussion forums.
• You have read the etcd bug reporting guidelines.
• Existing open issues along with etcd frequently asked questions have been checked and this is not a duplicate.

What happened?

Just yesterday we merged #20173 that added to both Robustness tests and Antithesis tests new type of client, one that connects to all members.

Within 1 day both frameworks found a new issue with watch: broke Bookmarkable - Progress notification events guarantee that all events up to a revision have been already delivered. Failures:

• Antithesis: https://linuxfoundation.antithesis.com/report/UZjUP_KGxboJepL7k1q_8pa4/ZqL0Vt9a7YESiiBmGecPMkBP8YgM1IwlTZJ4dcYjmZ8.html?auth=v2.public.eyJuYmYiOiIyMDI1LTA2LTI1VDAzOjE4OjIzLjM4MDU2MDQwMFoiLCJzY29wZSI6eyJSZXBvcnRTY29wZVYxIjp7ImFzc2V0IjoiWnFMMFZ0OWE3WUVTaWlCbUdlY1BNa0JQOFlnTTFJd2xUWko0ZGNZam1aOC5odG1sIiwicmVwb3J0X2lkIjoiVVpqVVBfS0d4Ym9KZXBMN2sxcV84cGE0In19feIAsYO4-UIigcL4eMu7QUqA6XFbCU3Hnw7BeyZW06o9x11mFqleHbSbRWdIcLdTH2Xzx42DXNB7dBqYq25Ujg4
• https://prow.k8s.io/view/gs/kubernetes-ci-logs/logs/ci-etcd-robustness-main-amd64/1937584192116232192

Example request for revision 148 returns event with revision 67.

{
  "Request": {
    "Key": "/registry/pods/",
    "Revision": 148,
    "WithPrefix": true,
    "WithProgressNotify": true,
    "WithPrevKV": true
  },
  "Responses": [
    {
      "Events": [
        {
          "Type": "put-operation",
          "Key": "/registry/pods/default/89523",
          "Value": {
            "Value": "65"
          },
          "Revision": 67,
          "PrevValue": {
            "Value": {
              "Value": "46"
            },
            "ModRevision": 35,
            "Version": 3
          }
        }
      ],
      "Revision": 67,
      "Time": 496351519816
    },

As this issue never appeared on clients connecting to single etcd member I expect this is an issue with client loadbalance/watch resume logic.

/cc @ahrtr @fuweid @siyuanfoundation @nwnt @joshjms @marcus-hodgson-antithesis

What did you expect to happen?

For watch request for revision 148, etcd should return revision not lower than 148.

How can we reproduce it (as minimally and precisely as possible)?

Report by Antithesis: var_report_dump.tar.gz
Report by Robustness: results.tar.gz

Anything else we need to know?

Needs to confirm this is a bug on etcd client side and not robustness recording side.

Etcd version (please run commands below)

Robustness found it on etcd main, Antithesis on release-3.6

Etcd configuration (command line flags or environment variables)

paste your configuration here

Etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

$ etcdctl member list -w table
# paste output here

$ etcdctl --endpoints=<member list> endpoint status -w table
# paste output here

Relevant log output

[serathius]

I'm guessing that might be caused by grpc loadbalancing not working well with stateful Watch ID connections. Potentially using same WatchID on different member.

[ahrtr]

How easily this issue can be reproduced?

Probably we can add a verification on server side to verify that the response event's revision >= watch revision (in request).

[marcus-hodgson-antithesis]

We can reproduce this in Antithesis! We're also able to interact with the live system at a frozen point in time where the failure happened. I've reached out to @serathius to schedule a debugging session sometime today.

[serathius]

Jumped on a call with @marcus-hodgson-antithesis to try Antithesis universe debugger, cool tool but debugging through a video call doesn't work well. Would love to get my hands on it.

In the mean time I managed to reproduce it locally on main branch, will try to repro it on other branches.

[serathius]

Issue reproduces on all minor versions, however I wasn't able to confirm that this is caused by client loadbalancing as I failed to swap to old old client version.

[serathius]

Added data about member that that watch response came from, looks my worry was confirmed:

   {
      "Events": [
        {
          "Type": "put-operation",
          "Key": "/registry/pods/default/IsUWQ",
          "Value": {
            "Value": "1928"
          },
          "Revision": 1453,
          "PrevValue": {
            "Value": {
              "Value": "1913"
            },
            "ModRevision": 1439,
            "Version": 9
          }
        }
      ],
      "Revision": 1453,
      "MemberId": 13770228943176794332,
      "Time": 1112225203
    },
    {
      "IsProgressNotify": true,
      "Revision": 1452,
      "MemberId": 12416079282240904009,
      "Time": 1232446330
    },

MemberId changes in an transparent way, meaning we switched etcd we talk to, resulting with incorrect watch stream response.

[ahrtr]

MemberId changes in an transparent way, meaning we switched etcd we talk to, resulting with incorrect watch stream response.

I manually tested this case, and did not see any issue. The client will automatically switch to another server if available when the current one is disconnected for whatever reason. In such case, the client will re-send the watch request with the correct rev, it doesn't have impact on the watch response.

It isn't clear whether the issue is test issue or server side issue.

[serathius]

It isn't clear whether the issue is test issue or server side issue.

Yes, I'm still confirming

[serathius]

I think I eliminated chance of this being a test error:

I have instrumented directly the etcd client code like so:

		fmt.Printf("Client %d open watch %d\n", c.ID, request.Revision)
		for r := range c.client.Watch(ctx, request.Key, ops...) {
			if len(r.Events) == 0 {
				fmt.Printf("Client %d member %d progress %d\n", c.ID, r.Header.MemberId, r.Header.Revision)
			} else {
				fmt.Printf("Client %d member %d events %d-%d\n", c.ID, r.Header.MemberId, r.Events[0].Kv.ModRevision, r.Events[len(r.Events)-1].Kv.ModRevision)
			}
		}
		fmt.Printf("Client %d close watch\n", c.ID)

And got the following results

Client 6 open watch 1475
Client 6 member 12416079282240904009 events 1475-1490
Client 6 member 12416079282240904009 events 1491-1491
Client 6 member 12416079282240904009 events 1492-1492
Client 6 member 12416079282240904009 events 1493-1493
Client 6 member 12416079282240904009 events 1494-1494
Client 6 member 12416079282240904009 events 1495-1495
Client 6 member 12416079282240904009 events 1496-1496
Client 6 member 12416079282240904009 events 1497-1497
Client 6 member 12416079282240904009 events 1498-1498
Client 6 member 12416079282240904009 events 1499-1499
Client 6 member 12416079282240904009 events 1500-1500
Client 6 member 12416079282240904009 events 1501-1501
Client 6 member 12416079282240904009 events 1502-1502
Client 6 member 12416079282240904009 events 1503-1503
Client 6 member 12416079282240904009 events 1504-1504
Client 6 member 12416079282240904009 events 1505-1505
Client 6 member 12416079282240904009 events 1506-1506
Client 6 member 12416079282240904009 events 1507-1507
Client 6 member 12416079282240904009 events 1508-1508
Client 6 member 12416079282240904009 events 1509-1509
Client 6 member 12416079282240904009 events 1510-1510
Client 6 member 12416079282240904009 events 1511-1511
Client 6 member 12416079282240904009 events 1512-1512
Client 6 member 12416079282240904009 events 1513-1513
Client 6 member 12416079282240904009 events 1514-1514
Client 6 member 12416079282240904009 events 1515-1515
Client 6 member 12416079282240904009 events 1516-1516
Client 6 member 12416079282240904009 events 1517-1517
Client 6 member 12416079282240904009 events 1518-1518
Client 6 member 12416079282240904009 events 1519-1519
Client 6 member 12416079282240904009 events 1520-1520
Client 6 member 12416079282240904009 events 1521-1521
Client 6 member 12416079282240904009 events 1522-1522
Client 6 member 12416079282240904009 events 1523-1523
Client 6 member 12416079282240904009 events 1524-1524
Client 6 member 12416079282240904009 events 1525-1525
Client 6 member 12416079282240904009 events 1526-1526
Client 6 member 12416079282240904009 events 1527-1527
Client 6 member 12416079282240904009 events 1528-1528
Client 6 member 12416079282240904009 events 1529-1529
Client 6 member 12416079282240904009 events 1530-1530
Client 6 member 12416079282240904009 events 1531-1531
Client 6 member 12416079282240904009 events 1532-1532
Client 6 member 12416079282240904009 events 1533-1533
Client 6 member 12416079282240904009 events 1534-1534
Client 6 member 12416079282240904009 events 1535-1535
Client 6 member 12416079282240904009 events 1536-1536
Client 6 member 12416079282240904009 events 1537-1537
Client 6 member 12416079282240904009 events 1538-1538
Client 6 member 12416079282240904009 events 1539-1539
Client 6 member 12416079282240904009 events 1540-1540
Client 6 member 12416079282240904009 events 1541-1541
Client 6 member 12416079282240904009 events 1542-1542
Client 6 member 12416079282240904009 events 1543-1543
Client 6 member 12416079282240904009 events 1544-1544
Client 6 member 12416079282240904009 events 1545-1545
Client 6 member 12416079282240904009 events 1546-1546
Client 6 member 12416079282240904009 events 1547-1547
Client 6 member 12416079282240904009 events 1548-1548
Client 6 member 12416079282240904009 events 1549-1549
Client 6 member 12416079282240904009 events 1550-1550
Client 6 member 12416079282240904009 events 1551-1551
Client 6 member 12416079282240904009 events 1552-1552
Client 6 member 12416079282240904009 events 1553-1553
Client 6 member 12416079282240904009 events 1554-1554
Client 6 member 12416079282240904009 events 1555-1555
Client 6 member 12416079282240904009 events 1556-1556
Client 6 member 12416079282240904009 events 1557-1557
Client 6 member 12416079282240904009 events 1558-1558
Client 6 member 12416079282240904009 events 1559-1559
Client 6 member 12416079282240904009 events 1560-1560
Client 6 member 12416079282240904009 events 1561-1561
Client 6 member 12416079282240904009 events 1562-1562
Client 6 member 12416079282240904009 events 1563-1563
Client 6 member 12416079282240904009 events 1564-1564
Client 6 member 12416079282240904009 events 1565-1565
Client 6 member 12416079282240904009 events 1566-1566
Client 6 member 12416079282240904009 events 1567-1567
Client 6 member 12416079282240904009 events 1568-1568
Client 6 member 12416079282240904009 events 1569-1569
Client 6 member 12416079282240904009 events 1570-1570
Client 6 member 12416079282240904009 events 1571-1571
Client 6 member 12416079282240904009 events 1572-1572
Client 6 member 12416079282240904009 events 1573-1573
Client 6 member 12416079282240904009 events 1574-1574
Client 6 member 12416079282240904009 events 1575-1575
Client 6 member 12416079282240904009 events 1576-1576
Client 6 member 12416079282240904009 events 1577-1577
Client 6 member 12416079282240904009 events 1578-1578
Client 6 member 12416079282240904009 events 1579-1579
Client 6 member 12416079282240904009 events 1580-1580
Client 6 member 12416079282240904009 events 1581-1581
Client 6 member 12416079282240904009 events 1582-1582
Client 6 member 12416079282240904009 events 1583-1583
Client 6 member 12416079282240904009 events 1584-1584
Client 6 member 12416079282240904009 events 1585-1585
Client 6 member 12416079282240904009 events 1586-1586
Client 6 member 12416079282240904009 events 1587-1587
Client 6 member 12416079282240904009 events 1588-1588
Client 6 member 12416079282240904009 events 1589-1589
Client 6 member 16914881897345358027 progress 1588
Client 6 member 16914881897345358027 progress 1588
Client 6 member 16914881897345358027 progress 1588
Client 6 member 16914881897345358027 progress 1588
Client 6 member 16914881897345358027 progress 1588
Client 6 member 16914881897345358027 progress 1588
Client 6 member 16914881897345358027 progress 1588
Client 6 member 16914881897345358027 progress 1588
Client 6 close watch
Client 6 open watch 1596
Client 6 member 13770228943176794332 events 1596-1604
Client 6 member 13770228943176794332 events 1605-1605
Client 6 member 13770228943176794332 events 1606-1606

The problematic sequence:

Client 6 member 12416079282240904009 events 1587-1587
Client 6 member 12416079282240904009 events 1588-1588
Client 6 member 12416079282240904009 events 1589-1589
Client 6 member 16914881897345358027 progress 1588
Client 6 member 16914881897345358027 progress 1588

[serathius]

One more possibility, client might be leaking control watch responses to caller and we might be incorrectly treating control responses as progress notify.

[ahrtr]

One more possibility, client might be leaking control watch responses to caller and we might be incorrectly treating control responses as progress notify.

It's possible,

etcd/server/etcdserver/api/v3rpc/watch.go

Line 447 in 795cca9

pending[wresp.WatchID] = wrs

etcd/server/etcdserver/api/v3rpc/watch.go

Lines 510 to 511 in 795cca9

	for _, v := range pending[wid] {
	mvcc.ReportEventReceived(len(v.Events))

Currently we don't have a clear way to differentiate a real progress notification and a ctrl response. But it isn't a problem based on our definition below. I think we are good as long as all events up to the progress revision have been already delivered

Bookmarkable - Progress notification events guarantee that all events up to a revision have been already delivered.

But the example in your very first comment, the watch response contained events which has a smaller revision then the request revision. Not sure whether it's just a test log "issue"

[ahrtr]

But the example in your very first comment, the watch response contained events which has a smaller revision then the request revision. Not sure whether it's just a test log "issue"

I meant this one,

{
  "Request": {
    "Key": "/registry/pods/",
    "Revision": 148,
    "WithPrefix": true,
    "WithProgressNotify": true,
    "WithPrevKV": true
  },
  "Responses": [
    {
      "Events": [
        {
          "Type": "put-operation",
          "Key": "/registry/pods/default/89523",
          "Value": {
            "Value": "65"
          },
          "Revision": 67,
          "PrevValue": {
            "Value": {
              "Value": "46"
            },
            "ModRevision": 35,
            "Version": 3
          }
        }
      ],
      "Revision": 67,
      "Time": 496351519816
    },