The test TestLeaseGrantAndList isn't stable

[ahrtr]

Sometimes it passes, but sometimes it fails. Use commands below to reproduce the issue.

$ cd tests/common
$ go test --tags integration -run TestLeaseGrantAndList

Error log:

    ......
    logger.go:130: 2022-03-31T02:54:21.444+0800	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc002fb7590, CONNECTING]
    logger.go:130: 2022-03-31T02:54:21.444+0800	INFO	grpc	[[core] Channel Connectivity change to CONNECTING]
    logger.go:130: 2022-03-31T02:54:21.451+0800	INFO	grpc	[[core] Subchannel Connectivity change to READY]
    logger.go:130: 2022-03-31T02:54:21.451+0800	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc002fb7590, READY]
    logger.go:130: 2022-03-31T02:54:21.451+0800	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[0xc002fb7590:{{unix:localhost:m-1 localhost <nil> 0 <nil>}}]}]
    logger.go:130: 2022-03-31T02:54:21.451+0800	INFO	grpc	[[core] Channel Connectivity change to READY]
    logger.go:130: 2022-03-31T02:54:21.566+0800	INFO	grpc	[[core] Channel Connectivity change to SHUTDOWN]
    logger.go:130: 2022-03-31T02:54:21.566+0800	INFO	grpc	[[core] Subchannel Connectivity change to SHUTDOWN]
    logger.go:130: 2022-03-31T02:54:21.566+0800	INFO	grpc	[[core] Channel Connectivity change to SHUTDOWN]
    logger.go:130: 2022-03-31T02:54:21.566+0800	INFO	grpc	[[core] Subchannel Connectivity change to SHUTDOWN]
    logger.go:130: 2022-03-31T02:54:21.566+0800	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-03-31T02:54:21.566+0800	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-03-31T02:54:21.567+0800	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-03-31T02:54:21.567+0800	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-03-31T02:54:21.567+0800	INFO	grpc	[[transport] transport: error closing conn during Close: tls: failed to send closeNotify alert (but connection was closed anyway): write unix localhost:m-1->: write: broken pipe]
    logger.go:130: 2022-03-31T02:54:21.567+0800	INFO	grpc	[[transport] transport: error closing conn during Close: tls: failed to send closeNotify alert (but connection was closed anyway): write unix localhost:m-1->: write: broken pipe]
FAIL
exit status 1
FAIL	go.etcd.io/etcd/tests/v3/common	17.077s

cc @endocrimes @kkkkun @serathius

[endocrimes]

Yeah it looks like the client doesn't use a stable etcd server, so sometimes hits one that hasn't got the latest state. I think I need to update it with some kind of Eventually check.

[lavacat]

I'll give this a shot
/assign

[lavacat]

I think the problem is that we can't rely on revision to stop polling. On server side we create leases list and then get Rev.
But there is no synchronization, so Leases can have older data, while Rev is newer.

s.lessor.Leases()
....
s.KV().Rev()

I think there are 2 solutions:

1. Use Len(leases)
2. Make an extra call to refresh leases after Rev condition is met.

I've submitted PR with 1

#13940

[serathius]

I think this was fixed in #13868

[lavacat]

@serathius I was able to reproduce it with #13868

cd tests/common
go test --tags integration -run TestLeaseGrantAndList

        lease_test.go:157:
            	Error Trace:	lease_test.go:157
            	            				execute.go:29
            	            				asm_amd64.s:1581
            	Error:      	elements differ

            	            	extra elements in list A:
            	            	([]interface {}) (len=1) {
            	            	 (clientv3.LeaseID) 5660321200314889477
            	            	}


            	            	listA:
            	            	([]clientv3.LeaseID) (len=3) {
            	            	 (clientv3.LeaseID) 6237626377548445188,
            	            	 (clientv3.LeaseID) 5013210228857097476,
            	            	 (clientv3.LeaseID) 5660321200314889477
            	            	}


            	            	listB:
            	            	([]clientv3.LeaseID) (len=2) {
            	            	 (clientv3.LeaseID) 6237626377548445188,
            	            	 (clientv3.LeaseID) 5013210228857097476
            	            	}
            	Test:       	TestLeaseGrantAndList/PeerTLS/many_leases

[serathius]

Interesting as in my case it doesn't fail even with 50 runs, when without #13868 it reproduces within couple of runs.

[lavacat]

IMO the core issue is getting revision at the end of LeaseLeases function
https://github.com/etcd-io/etcd/blob/main/server/etcdserver/v3_server.go#L399

It's not guaranteed that lss list actually reflects latest Revision. Maybe a better fix is to move newHeader() to the start of LeaseLeases.

[lavacat]

@endocrimes since you are the author of #13868, can you check my fix #13940 ?

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 21 days if no further activity occurs. Thank you for your contributions.