Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

TestEtcdClientSync is flaky #8085

Open
rleungx opened this issue Apr 17, 2024 · 2 comments · Fixed by #8084
Open

TestEtcdClientSync is flaky #8085

rleungx opened this issue Apr 17, 2024 · 2 comments · Fixed by #8084
Labels
type/ci The issue is related to CI.

Comments

@rleungx
Copy link
Member

rleungx commented Apr 17, 2024

Flaky Test

Which jobs are failing

--- FAIL: TestEtcdClientSync (0.86s)
    etcdutil_test.go:185: 
        	Error Trace:	/home/runner/work/pd/pd/pkg/utils/etcdutil/etcdutil_test.go:185
        	Error:      	Received unexpected error:
        	            	[PD:etcd:ErrEtcdMemberRemove]etcdserver: server stopped: etcdserver: server stopped
        	            	github.com/pingcap/errors.AddStack
        	            		/home/runner/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174
        	            	github.com/pingcap/errors.(*Error).GenWithStackByCause
        	            		/home/runner/go/pkg/mod/github.com/pingcap/[email protected]/normalize.go:307
        	            	github.com/tikv/pd/pkg/utils/etcdutil.RemoveEtcdMember
        	            		/home/runner/work/pd/pd/pkg/utils/etcdutil/etcdutil.go:136
        	            	github.com/tikv/pd/pkg/utils/etcdutil.TestEtcdClientSync
        	            		/home/runner/work/pd/pd/pkg/utils/etcdutil/etcdutil_test.go:184
        	            	testing.tRunner
        	            		/opt/hostedtoolcache/go/1.21.9/x64/src/testing/testing.go:1595
        	            	runtime.goexit
        	            		/opt/hostedtoolcache/go/1.21.9/x64/src/runtime/asm_amd64.s:1650
        	Test:       	TestEtcdClientSync

CI link

https://github.com/tikv/pd/actions/runs/8718669939/job/23916391513?pr=8082

Reason for failure (if possible)

Anything else
@rleungx rleungx added the type/ci The issue is related to CI. label Apr 17, 2024
@rleungx rleungx mentioned this issue Apr 17, 2024
Merged
ti-chi-bot bot added a commit that referenced this issue Apr 17, 2024
@rleungx @ti-chi-bot
*: make TestEtcdClientSync stable (#8084)
afdd48f 
close #8085

Signed-off-by: Ryan Leung <[email protected]>

Co-authored-by: ti-chi-bot[bot] <108142056+ti-chi-bot[bot]@users.noreply.github.com>
@lhy1024
Copy link
Contributor

lhy1024 commented Apr 23, 2024 

2024-04-23T06:55:55.9231651Z --- FAIL: TestEtcdClientSync (0.88s)
2024-04-23T06:55:55.9232127Z     etcdutil_test.go:199: 
2024-04-23T06:55:55.9232909Z         	Error Trace:	/home/runner/work/pd/pd/pkg/utils/etcdutil/etcdutil_test.go:199
2024-04-23T06:55:55.9233719Z         	Error:      	Received unexpected error:
2024-04-23T06:55:55.9234787Z         	            	[PD:etcd:ErrEtcdMemberRemove]etcdserver: server stopped: etcdserver: server stopped
2024-04-23T06:55:55.9235639Z         	            	github.com/pingcap/errors.AddStack
2024-04-23T06:55:55.9237146Z         	            		/home/runner/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174
2024-04-23T06:55:55.9238280Z         	            	github.com/pingcap/errors.(*Error).GenWithStackByCause
2024-04-23T06:55:55.9239879Z         	            		/home/runner/go/pkg/mod/github.com/pingcap/[email protected]/normalize.go:307
2024-04-23T06:55:55.9241015Z         	            	github.com/tikv/pd/pkg/utils/etcdutil.RemoveEtcdMember
2024-04-23T06:55:55.9242025Z         	            		/home/runner/work/pd/pd/pkg/utils/etcdutil/etcdutil.go:136
2024-04-23T06:55:55.9243000Z         	            	github.com/tikv/pd/pkg/utils/etcdutil.TestEtcdClientSync
2024-04-23T06:55:55.9244077Z         	            		/home/runner/work/pd/pd/pkg/utils/etcdutil/etcdutil_test.go:198
2024-04-23T06:55:55.9244777Z         	            	testing.tRunner
2024-04-23T06:55:55.9245760Z         	            		/opt/hostedtoolcache/go/1.21.9/x64/src/testing/testing.go:1595
2024-04-23T06:55:55.9246460Z         	            	runtime.goexit
2024-04-23T06:55:55.9247287Z         	            		/opt/hostedtoolcache/go/1.21.9/x64/src/runtime/asm_amd64.s:1650
2024-04-23T06:55:55.9247988Z         	Test:       	TestEtcdClientSync

https://github.com/tikv/pd/actions/runs/8796064689/job/24138225547?pr=8116

@lhy1024 lhy1024 reopened this Apr 23, 2024
@okJiang
Copy link
Member

okJiang commented Jul 10, 2024

I tried this test on my local Mac, and every time I encountered this issue, here is the error log. I observed that after member 2(8195c4f470081d6c, "http://127.0.0.1:57908") exited, member 1(517aa5d5512611cd, "http://127.0.0.1:57902") also exited by itself, causing the error later on. However, I couldn't find the reason why member 1 exited along with member 2.

error.log

Running tool: /usr/local/go/bin/go test -timeout 600s -run ^TestEtcdClientSync$ github.com/tikv/pd/pkg/utils/etcdutil -race --tags=intest

{"level":"warn","ts":"2024-07-10T15:15:00.093994+0800","caller":"embed/config.go:622","msg":"Running http and grpc server on single port. This is not recommended for production."}
{"level":"info","ts":"2024-07-10T15:15:00.094253+0800","caller":"embed/etcd.go:120","msg":"configuring peer listeners","listen-peer-urls":["http://127.0.0.1:57901"]}
{"level":"info","ts":"2024-07-10T15:15:00.094359+0800","caller":"embed/etcd.go:130","msg":"configuring client listeners","listen-client-urls":["http://127.0.0.1:57902"]}
{"level":"info","ts":"2024-07-10T15:15:00.09449+0800","caller":"embed/etcd.go:309","msg":"starting an etcd server","etcd-version":"3.4.31","git-sha":"Not provided (use ./build instead of go build)","go-version":"go1.21.2","go-os":"darwin","go-arch":"arm64","max-cpu-set":8,"max-cpu-available":8,"member-initialized":false,"name":"test_etcd_1720595700092998000","data-dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/001","wal-dir":"","wal-dir-dedicated":"","member-dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/001/member","force-new-cluster":false,"heartbeat-interval":"100ms","election-timeout":"1s","initial-election-tick-advance":true,"snapshot-count":100000,"max-wals":5,"max-snapshots":5,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["http://127.0.0.1:57901"],"listen-peer-urls":["http://127.0.0.1:57901"],"advertise-client-urls":["http://127.0.0.1:57902"],"listen-client-urls":["http://127.0.0.1:57902"],"listen-metrics-urls":[],"cors":[""],"host-whitelist":[""],"initial-cluster":"test_etcd_1720595700092998000=http://127.0.0.1:57901","initial-cluster-state":"new","initial-cluster-token":"etcd-cluster","quota-backend-bytes":2147483648,"max-request-bytes":1572864,"max-concurrent-streams":4294967295,"pre-vote":false,"initial-corrupt-check":false,"corrupt-check-time-interval":"0s","auto-compaction-mode":"","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":""}
2024-07-10 15:15:00.094624 W | pkg/fileutil: check file permission: directory "/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/001" exist, but the permission is "drwxr-xr-x". The recommended permission is "-rwx------" to prevent possible unprivileged access to the data.
{"level":"info","ts":"2024-07-10T15:15:00.106141+0800","caller":"etcdserver/backend.go:80","msg":"opened backend db","path":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/001/member/snap/db","took":"10.731375ms"}
{"level":"info","ts":"2024-07-10T15:15:00.166421+0800","caller":"etcdserver/raft.go:537","msg":"starting local member","local-member-id":"517aa5d5512611cd","cluster-id":"7775bdc730413de5"}
{"level":"info","ts":"2024-07-10T15:15:00.166814+0800","caller":"raft/raft.go:1523","msg":"517aa5d5512611cd switched to configuration voters=()"}
{"level":"info","ts":"2024-07-10T15:15:00.166941+0800","caller":"raft/raft.go:706","msg":"517aa5d5512611cd became follower at term 0"}
{"level":"info","ts":"2024-07-10T15:15:00.166975+0800","caller":"raft/raft.go:389","msg":"newRaft 517aa5d5512611cd [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"}
{"level":"info","ts":"2024-07-10T15:15:00.167003+0800","caller":"raft/raft.go:706","msg":"517aa5d5512611cd became follower at term 1"}
{"level":"info","ts":"2024-07-10T15:15:00.167099+0800","caller":"raft/raft.go:1523","msg":"517aa5d5512611cd switched to configuration voters=(5871187399838929357)"}
{"level":"warn","ts":"2024-07-10T15:15:00.181112+0800","caller":"auth/store.go:1391","msg":"simple token is not cryptographically signed"}
{"level":"info","ts":"2024-07-10T15:15:00.201183+0800","caller":"etcdserver/quota.go:98","msg":"enabled backend quota with default value","quota-name":"v3-applier","quota-size-bytes":2147483648,"quota-size":"2.1 GB"}
{"level":"info","ts":"2024-07-10T15:15:00.211079+0800","caller":"etcdserver/server.go:831","msg":"starting etcd server","local-member-id":"517aa5d5512611cd","local-server-version":"3.4.31","cluster-version":"to_be_decided"}
{"level":"info","ts":"2024-07-10T15:15:00.211337+0800","caller":"fileutil/purge.go:48","msg":"started to purge file","dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/001/member/snap","suffix":"snap.db","max":5,"interval":"30s"}
{"level":"info","ts":"2024-07-10T15:15:00.211642+0800","caller":"fileutil/purge.go:48","msg":"started to purge file","dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/001/member/snap","suffix":"snap","max":5,"interval":"30s"}
{"level":"info","ts":"2024-07-10T15:15:00.211424+0800","caller":"etcdserver/server.go:697","msg":"started as single-node; fast-forwarding election ticks","local-member-id":"517aa5d5512611cd","forward-ticks":9,"forward-duration":"900ms","election-ticks":10,"election-timeout":"1s"}
{"level":"info","ts":"2024-07-10T15:15:00.211696+0800","caller":"fileutil/purge.go:48","msg":"started to purge file","dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/001/member/wal","suffix":"wal","max":5,"interval":"30s"}
{"level":"warn","ts":"2024-07-10T15:15:00.21159+0800","caller":"etcdserver/metrics.go:213","msg":"failed to get file descriptor usage","error":"cannot get FDUsage on darwin"}
{"level":"info","ts":"2024-07-10T15:15:00.216362+0800","caller":"embed/etcd.go:605","msg":"serving peer traffic","address":"127.0.0.1:57901"}
{"level":"info","ts":"2024-07-10T15:15:00.216395+0800","caller":"raft/raft.go:1523","msg":"517aa5d5512611cd switched to configuration voters=(5871187399838929357)"}
{"level":"info","ts":"2024-07-10T15:15:00.216415+0800","caller":"embed/etcd.go:251","msg":"now serving peer/client/metrics","local-member-id":"517aa5d5512611cd","initial-advertise-peer-urls":["http://127.0.0.1:57901"],"listen-peer-urls":["http://127.0.0.1:57901"],"advertise-client-urls":["http://127.0.0.1:57902"],"listen-client-urls":["http://127.0.0.1:57902"],"listen-metrics-urls":[]}
{"level":"info","ts":"2024-07-10T15:15:00.217221+0800","caller":"membership/cluster.go:395","msg":"added member","cluster-id":"7775bdc730413de5","local-member-id":"517aa5d5512611cd","added-peer-id":"517aa5d5512611cd","added-peer-peer-urls":["http://127.0.0.1:57901"]}
{"level":"info","ts":"2024-07-10T15:15:00.769457+0800","caller":"raft/raft.go:929","msg":"517aa5d5512611cd is starting a new election at term 1"}
{"level":"info","ts":"2024-07-10T15:15:00.769615+0800","caller":"raft/raft.go:719","msg":"517aa5d5512611cd became candidate at term 2"}
{"level":"info","ts":"2024-07-10T15:15:00.769703+0800","caller":"raft/raft.go:830","msg":"517aa5d5512611cd received MsgVoteResp from 517aa5d5512611cd at term 2"}
{"level":"info","ts":"2024-07-10T15:15:00.769786+0800","caller":"raft/raft.go:771","msg":"517aa5d5512611cd became leader at term 2"}
{"level":"info","ts":"2024-07-10T15:15:00.769846+0800","caller":"raft/node.go:327","msg":"raft.node: 517aa5d5512611cd elected leader 517aa5d5512611cd at term 2"}
{"level":"info","ts":"2024-07-10T15:15:00.775434+0800","caller":"etcdserver/server.go:2639","msg":"setting up initial cluster version","cluster-version":"3.4"}
{"level":"info","ts":"2024-07-10T15:15:00.775708+0800","caller":"etcdserver/server.go:2140","msg":"published local member to cluster through raft","local-member-id":"517aa5d5512611cd","local-member-attributes":"{Name:test_etcd_1720595700092998000 ClientURLs:[http://127.0.0.1:57902]}","request-path":"/0/members/517aa5d5512611cd/attributes","cluster-id":"7775bdc730413de5","publish-timeout":"7s"}
{"level":"info","ts":"2024-07-10T15:15:00.775793+0800","caller":"embed/serve.go:100","msg":"ready to serve client requests"}
{"level":"info","ts":"2024-07-10T15:15:00.779025+0800","caller":"embed/serve.go:209","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"127.0.0.1:57902"}
{"level":"info","ts":"2024-07-10T15:15:00.780134+0800","caller":"membership/cluster.go:561","msg":"set initial cluster version","cluster-id":"7775bdc730413de5","local-member-id":"517aa5d5512611cd","cluster-version":"3.4"}
{"level":"info","ts":"2024-07-10T15:15:00.780257+0800","caller":"api/capability.go:77","msg":"enabled capabilities for version","cluster-version":"3.4"}
{"level":"info","ts":"2024-07-10T15:15:00.780304+0800","caller":"etcdserver/server.go:2671","msg":"cluster version is updated","cluster-version":"3.4"}
{"level":"info","ts":"2024-07-10T15:15:00.88642+0800","caller":"raft/raft.go:1523","msg":"517aa5d5512611cd switched to configuration voters=(5871187399838929357 9337585956553235820)"}
{"level":"info","ts":"2024-07-10T15:15:00.886892+0800","caller":"membership/cluster.go:395","msg":"added member","cluster-id":"7775bdc730413de5","local-member-id":"517aa5d5512611cd","added-peer-id":"8195c4f470081d6c","added-peer-peer-urls":["http://127.0.0.1:57907"]}
{"level":"info","ts":"2024-07-10T15:15:00.887251+0800","caller":"rafthttp/peer.go:128","msg":"starting remote peer","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:00.887437+0800","caller":"rafthttp/pipeline.go:71","msg":"started HTTP pipelining with remote peer","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:00.889254+0800","caller":"rafthttp/stream.go:166","msg":"started stream writer with remote peer","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:00.889863+0800","caller":"rafthttp/stream.go:166","msg":"started stream writer with remote peer","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:00.890329+0800","caller":"rafthttp/peer.go:134","msg":"started remote peer","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:00.890464+0800","caller":"rafthttp/transport.go:327","msg":"added remote peer","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c","remote-peer-urls":["http://127.0.0.1:57907"]}
{"level":"info","ts":"2024-07-10T15:15:00.890405+0800","caller":"rafthttp/stream.go:406","msg":"started stream reader with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:00.890461+0800","caller":"rafthttp/stream.go:406","msg":"started stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:00.890539+0800","caller":"etcdserver/server.go:2068","msg":"applied a configuration change through raft","local-member-id":"517aa5d5512611cd","raft-conf-change":"ConfChangeAddNode","raft-conf-change-node-id":"8195c4f470081d6c"}
{"level":"warn","ts":"2024-07-10T15:15:00.993573+0800","caller":"embed/config.go:622","msg":"Running http and grpc server on single port. This is not recommended for production."}
{"level":"info","ts":"2024-07-10T15:15:00.993715+0800","caller":"embed/etcd.go:120","msg":"configuring peer listeners","listen-peer-urls":["http://127.0.0.1:57907"]}
{"level":"info","ts":"2024-07-10T15:15:00.993919+0800","caller":"embed/etcd.go:130","msg":"configuring client listeners","listen-client-urls":["http://127.0.0.1:57908"]}
{"level":"info","ts":"2024-07-10T15:15:00.994369+0800","caller":"embed/etcd.go:309","msg":"starting an etcd server","etcd-version":"3.4.31","git-sha":"Not provided (use ./build instead of go build)","go-version":"go1.21.2","go-os":"darwin","go-arch":"arm64","max-cpu-set":8,"max-cpu-available":8,"member-initialized":false,"name":"test_etcd_1720595700879944000","data-dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/002","wal-dir":"","wal-dir-dedicated":"","member-dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/002/member","force-new-cluster":false,"heartbeat-interval":"100ms","election-timeout":"1s","initial-election-tick-advance":true,"snapshot-count":100000,"max-wals":5,"max-snapshots":5,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["http://127.0.0.1:57907"],"listen-peer-urls":["http://127.0.0.1:57907"],"advertise-client-urls":["http://127.0.0.1:57908"],"listen-client-urls":["http://127.0.0.1:57908"],"listen-metrics-urls":[],"cors":[""],"host-whitelist":[""],"initial-cluster":"test_etcd_1720595700092998000=http://127.0.0.1:57901,test_etcd_1720595700879944000=http://127.0.0.1:57907","initial-cluster-state":"existing","initial-cluster-token":"etcd-cluster","quota-backend-bytes":2147483648,"max-request-bytes":1572864,"max-concurrent-streams":4294967295,"pre-vote":false,"initial-corrupt-check":false,"corrupt-check-time-interval":"0s","auto-compaction-mode":"","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":""}
2024-07-10 15:15:00.994735 W | pkg/fileutil: check file permission: directory "/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/002" exist, but the permission is "drwxr-xr-x". The recommended permission is "-rwx------" to prevent possible unprivileged access to the data.
{"level":"info","ts":"2024-07-10T15:15:01.000275+0800","caller":"etcdserver/backend.go:80","msg":"opened backend db","path":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/002/member/snap/db","took":"4.291667ms"}
{"level":"info","ts":"2024-07-10T15:15:01.002179+0800","caller":"netutil/netutil.go:112","msg":"resolved URL Host","url":"http://127.0.0.1:57907","host":"127.0.0.1:57907","resolved-addr":"127.0.0.1:57907"}
{"level":"info","ts":"2024-07-10T15:15:01.002299+0800","caller":"netutil/netutil.go:112","msg":"resolved URL Host","url":"http://127.0.0.1:57901","host":"127.0.0.1:57901","resolved-addr":"127.0.0.1:57901"}
[2024/07/10 15:15:01.020 +08:00] [WARN] [retry_interceptor.go:62] ["retrying of unary invoker failed"] [target=etcd-endpoints://0xc000b46960/127.0.0.1:57902] [attempt=0] [error="rpc error: code = DeadlineExceeded desc = context deadline exceeded"]
[2024/07/10 15:15:01.020 +08:00] [WARN] [health_checker.go:194] ["etcd endpoint is unhealthy"] [endpoint=http://127.0.0.1:57902] [took=100.324709ms] [source=default-etcd-client]
{"level":"info","ts":"2024-07-10T15:15:01.041055+0800","caller":"etcdserver/raft.go:537","msg":"starting local member","local-member-id":"8195c4f470081d6c","cluster-id":"7775bdc730413de5"}
{"level":"info","ts":"2024-07-10T15:15:01.041402+0800","caller":"raft/raft.go:1523","msg":"8195c4f470081d6c switched to configuration voters=()"}
{"level":"info","ts":"2024-07-10T15:15:01.041452+0800","caller":"raft/raft.go:706","msg":"8195c4f470081d6c became follower at term 0"}
{"level":"info","ts":"2024-07-10T15:15:01.041482+0800","caller":"raft/raft.go:389","msg":"newRaft 8195c4f470081d6c [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"}
{"level":"warn","ts":"2024-07-10T15:15:01.059998+0800","caller":"auth/store.go:1391","msg":"simple token is not cryptographically signed"}
{"level":"info","ts":"2024-07-10T15:15:01.08523+0800","caller":"rafthttp/pipeline.go:71","msg":"started HTTP pipelining with remote peer","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.085289+0800","caller":"rafthttp/transport.go:294","msg":"added new remote peer","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd","remote-peer-urls":["http://127.0.0.1:57901"]}
{"level":"info","ts":"2024-07-10T15:15:01.085487+0800","caller":"rafthttp/peer.go:128","msg":"starting remote peer","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.085559+0800","caller":"rafthttp/pipeline.go:71","msg":"started HTTP pipelining with remote peer","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.085677+0800","caller":"rafthttp/stream.go:166","msg":"started stream writer with remote peer","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.085766+0800","caller":"rafthttp/stream.go:166","msg":"started stream writer with remote peer","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.085949+0800","caller":"rafthttp/peer.go:134","msg":"started remote peer","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.085972+0800","caller":"rafthttp/stream.go:406","msg":"started stream reader with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.086008+0800","caller":"rafthttp/stream.go:406","msg":"started stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.086374+0800","caller":"rafthttp/transport.go:327","msg":"added remote peer","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd","remote-peer-urls":["http://127.0.0.1:57901"]}
{"level":"info","ts":"2024-07-10T15:15:01.086446+0800","caller":"etcdserver/server.go:831","msg":"starting etcd server","local-member-id":"8195c4f470081d6c","local-server-version":"3.4.31","cluster-version":"to_be_decided"}
{"level":"info","ts":"2024-07-10T15:15:01.086759+0800","caller":"etcdserver/server.go:719","msg":"starting initial election tick advance","election-ticks":10}
{"level":"info","ts":"2024-07-10T15:15:01.086939+0800","caller":"fileutil/purge.go:48","msg":"started to purge file","dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/002/member/snap","suffix":"snap.db","max":5,"interval":"30s"}
{"level":"info","ts":"2024-07-10T15:15:01.086979+0800","caller":"fileutil/purge.go:48","msg":"started to purge file","dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/002/member/snap","suffix":"snap","max":5,"interval":"30s"}
{"level":"info","ts":"2024-07-10T15:15:01.087127+0800","caller":"fileutil/purge.go:48","msg":"started to purge file","dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/002/member/wal","suffix":"wal","max":5,"interval":"30s"}
{"level":"warn","ts":"2024-07-10T15:15:01.08708+0800","caller":"etcdserver/metrics.go:213","msg":"failed to get file descriptor usage","error":"cannot get FDUsage on darwin"}
{"level":"info","ts":"2024-07-10T15:15:01.088101+0800","caller":"rafthttp/stream.go:250","msg":"set message encoder","from":"517aa5d5512611cd","to":"517aa5d5512611cd","stream-type":"stream Message"}
{"level":"info","ts":"2024-07-10T15:15:01.088109+0800","caller":"rafthttp/stream.go:250","msg":"set message encoder","from":"517aa5d5512611cd","to":"517aa5d5512611cd","stream-type":"stream MsgApp v2"}
{"level":"info","ts":"2024-07-10T15:15:01.08814+0800","caller":"rafthttp/peer_status.go:51","msg":"peer became active","peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:01.088188+0800","caller":"rafthttp/peer_status.go:51","msg":"peer became active","peer-id":"517aa5d5512611cd"}
{"level":"warn","ts":"2024-07-10T15:15:01.088239+0800","caller":"rafthttp/stream.go:277","msg":"established TCP streaming connection with remote peer","stream-writer-type":"stream MsgApp v2","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"warn","ts":"2024-07-10T15:15:01.088198+0800","caller":"rafthttp/stream.go:277","msg":"established TCP streaming connection with remote peer","stream-writer-type":"stream Message","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:01.088279+0800","caller":"rafthttp/stream.go:425","msg":"established TCP streaming connection with remote peer","stream-reader-type":"stream Message","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.08831+0800","caller":"rafthttp/stream.go:425","msg":"established TCP streaming connection with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.08882+0800","caller":"embed/etcd.go:605","msg":"serving peer traffic","address":"127.0.0.1:57907"}
{"level":"info","ts":"2024-07-10T15:15:01.088998+0800","caller":"embed/etcd.go:251","msg":"now serving peer/client/metrics","local-member-id":"8195c4f470081d6c","initial-advertise-peer-urls":["http://127.0.0.1:57907"],"listen-peer-urls":["http://127.0.0.1:57907"],"advertise-client-urls":["http://127.0.0.1:57908"],"listen-client-urls":["http://127.0.0.1:57908"],"listen-metrics-urls":[]}
{"level":"info","ts":"2024-07-10T15:15:01.089086+0800","caller":"raft/raft.go:865","msg":"8195c4f470081d6c [term: 0] received a MsgHeartbeat message with higher term from 517aa5d5512611cd [term: 2]"}
{"level":"info","ts":"2024-07-10T15:15:01.089128+0800","caller":"raft/raft.go:706","msg":"8195c4f470081d6c became follower at term 2"}
{"level":"info","ts":"2024-07-10T15:15:01.089162+0800","caller":"raft/node.go:327","msg":"raft.node: 8195c4f470081d6c elected leader 517aa5d5512611cd at term 2"}
{"level":"info","ts":"2024-07-10T15:15:01.091942+0800","caller":"rafthttp/stream.go:250","msg":"set message encoder","from":"8195c4f470081d6c","to":"8195c4f470081d6c","stream-type":"stream Message"}
{"level":"warn","ts":"2024-07-10T15:15:01.091976+0800","caller":"rafthttp/stream.go:277","msg":"established TCP streaming connection with remote peer","stream-writer-type":"stream Message","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.092044+0800","caller":"rafthttp/stream.go:425","msg":"established TCP streaming connection with remote peer","stream-reader-type":"stream Message","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:01.092155+0800","caller":"rafthttp/stream.go:425","msg":"established TCP streaming connection with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:01.092278+0800","caller":"rafthttp/stream.go:250","msg":"set message encoder","from":"8195c4f470081d6c","to":"8195c4f470081d6c","stream-type":"stream MsgApp v2"}
{"level":"warn","ts":"2024-07-10T15:15:01.092348+0800","caller":"rafthttp/stream.go:277","msg":"established TCP streaming connection with remote peer","stream-writer-type":"stream MsgApp v2","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.093145+0800","caller":"traceutil/trace.go:152","msg":"trace[234123624] linearizableReadLoop","detail":"{readStateIndex:5; appliedIndex:5; }","duration":"172.254334ms","start":"2024-07-10T15:15:00.920847+0800","end":"2024-07-10T15:15:01.093102+0800","steps":["trace[234123624] 'read index received' (duration: 172.249709ms)","trace[234123624] 'applied index is now lower than readState.Index' (duration: 3.125µs)"]}
{"level":"info","ts":"2024-07-10T15:15:01.102068+0800","caller":"raft/raft.go:1523","msg":"8195c4f470081d6c switched to configuration voters=(5871187399838929357)"}
{"level":"info","ts":"2024-07-10T15:15:01.102221+0800","caller":"membership/cluster.go:395","msg":"added member","cluster-id":"7775bdc730413de5","local-member-id":"8195c4f470081d6c","added-peer-id":"517aa5d5512611cd","added-peer-peer-urls":["http://127.0.0.1:57901"]}
{"level":"info","ts":"2024-07-10T15:15:01.102407+0800","caller":"membership/cluster.go:561","msg":"set initial cluster version","cluster-id":"7775bdc730413de5","local-member-id":"8195c4f470081d6c","cluster-version":"3.4"}
{"level":"info","ts":"2024-07-10T15:15:01.102611+0800","caller":"raft/raft.go:1523","msg":"8195c4f470081d6c switched to configuration voters=(5871187399838929357 9337585956553235820)"}
{"level":"info","ts":"2024-07-10T15:15:01.10272+0800","caller":"membership/cluster.go:395","msg":"added member","cluster-id":"7775bdc730413de5","local-member-id":"8195c4f470081d6c","added-peer-id":"8195c4f470081d6c","added-peer-peer-urls":["http://127.0.0.1:57907"]}
{"level":"info","ts":"2024-07-10T15:15:01.103152+0800","caller":"etcdserver/server.go:2140","msg":"published local member to cluster through raft","local-member-id":"8195c4f470081d6c","local-member-attributes":"{Name:test_etcd_1720595700879944000 ClientURLs:[http://127.0.0.1:57908]}","request-path":"/0/members/8195c4f470081d6c/attributes","cluster-id":"7775bdc730413de5","publish-timeout":"7s"}
{"level":"info","ts":"2024-07-10T15:15:01.103166+0800","caller":"embed/serve.go:100","msg":"ready to serve client requests"}
{"level":"info","ts":"2024-07-10T15:15:01.104392+0800","caller":"embed/serve.go:209","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"127.0.0.1:57908"}
[2024/07/10 15:15:01.223 +08:00] [INFO] [health_checker.go:137] ["update endpoints"] [num-change=1->2] [last-endpoints="[http://127.0.0.1:57902]"] [endpoints="[http://127.0.0.1:57902,http://127.0.0.1:57908]"] [source=default-etcd-client]
{"level":"info","ts":"2024-07-10T15:15:01.316656+0800","caller":"raft/raft.go:1523","msg":"517aa5d5512611cd switched to configuration voters=(5871187399838929357)"}
{"level":"info","ts":"2024-07-10T15:15:01.316807+0800","caller":"raft/raft.go:1523","msg":"8195c4f470081d6c switched to configuration voters=(5871187399838929357)"}
{"level":"info","ts":"2024-07-10T15:15:01.329993+0800","caller":"membership/cluster.go:425","msg":"removed member","cluster-id":"7775bdc730413de5","local-member-id":"517aa5d5512611cd","removed-remote-peer-id":"8195c4f470081d6c","removed-remote-peer-urls":["http://127.0.0.1:57907"]}
{"level":"info","ts":"2024-07-10T15:15:01.330067+0800","caller":"rafthttp/peer.go:333","msg":"stopping remote peer","remote-peer-id":"8195c4f470081d6c"}
{"level":"warn","ts":"2024-07-10T15:15:01.330166+0800","caller":"rafthttp/stream.go:291","msg":"closed TCP streaming connection with remote peer","stream-writer-type":"stream MsgApp v2","remote-peer-id":"8195c4f470081d6c"}
{"level":"warn","ts":"2024-07-10T15:15:01.330205+0800","caller":"rafthttp/stream.go:301","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"stream MsgApp v2","remote-peer-id":"8195c4f470081d6c"}
{"level":"warn","ts":"2024-07-10T15:15:01.330281+0800","caller":"rafthttp/stream.go:291","msg":"closed TCP streaming connection with remote peer","stream-writer-type":"stream Message","remote-peer-id":"8195c4f470081d6c"}
{"level":"warn","ts":"2024-07-10T15:15:01.33029+0800","caller":"rafthttp/stream.go:436","msg":"lost TCP streaming connection with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd","error":"EOF"}
{"level":"warn","ts":"2024-07-10T15:15:01.330314+0800","caller":"rafthttp/stream.go:301","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"stream Message","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:01.330377+0800","caller":"rafthttp/pipeline.go:86","msg":"stopped HTTP pipelining with remote peer","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"warn","ts":"2024-07-10T15:15:01.330413+0800","caller":"rafthttp/stream.go:436","msg":"lost TCP streaming connection with remote peer","stream-reader-type":"stream Message","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd","error":"EOF"}
{"level":"warn","ts":"2024-07-10T15:15:01.330562+0800","caller":"rafthttp/stream.go:436","msg":"lost TCP streaming connection with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c","error":"context canceled"}
{"level":"warn","ts":"2024-07-10T15:15:01.330606+0800","caller":"rafthttp/peer_status.go:68","msg":"peer became inactive (message send to peer failed)","peer-id":"8195c4f470081d6c","error":"failed to read 8195c4f470081d6c on stream MsgApp v2 (context canceled)"}
{"level":"info","ts":"2024-07-10T15:15:01.330654+0800","caller":"rafthttp/stream.go:459","msg":"stopped stream reader with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"warn","ts":"2024-07-10T15:15:01.33183+0800","caller":"rafthttp/stream.go:436","msg":"lost TCP streaming connection with remote peer","stream-reader-type":"stream Message","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c","error":"context canceled"}
{"level":"info","ts":"2024-07-10T15:15:01.331871+0800","caller":"rafthttp/stream.go:459","msg":"stopped stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"517aa5d5512611cd","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:01.331913+0800","caller":"rafthttp/peer.go:340","msg":"stopped remote peer","remote-peer-id":"8195c4f470081d6c"}
{"level":"info","ts":"2024-07-10T15:15:01.331946+0800","caller":"rafthttp/transport.go:369","msg":"removed remote peer","local-member-id":"517aa5d5512611cd","removed-remote-peer-id":"8195c4f470081d6c"}
{"level":"warn","ts":"2024-07-10T15:15:01.33226+0800","caller":"rafthttp/http.go:425","msg":"rejected stream from remote peer because it was removed","local-member-id":"517aa5d5512611cd","remote-peer-id-stream-handler":"517aa5d5512611cd","remote-peer-id-from":"8195c4f470081d6c"}
{"level":"warn","ts":"2024-07-10T15:15:01.332449+0800","caller":"rafthttp/http.go:425","msg":"rejected stream from remote peer because it was removed","local-member-id":"517aa5d5512611cd","remote-peer-id-stream-handler":"517aa5d5512611cd","remote-peer-id-from":"8195c4f470081d6c"}
{"level":"warn","ts":"2024-07-10T15:15:01.332459+0800","caller":"rafthttp/peer_status.go:68","msg":"peer became inactive (message send to peer failed)","peer-id":"517aa5d5512611cd","error":"failed to dial 517aa5d5512611cd on stream MsgApp v2 (the member has been permanently removed from the cluster)"}
{"level":"warn","ts":"2024-07-10T15:15:01.33245+0800","caller":"etcdserver/server.go:1093","msg":"server error","error":"the member has been permanently removed from the cluster"}
{"level":"warn","ts":"2024-07-10T15:15:01.332557+0800","caller":"etcdserver/server.go:1094","msg":"data-dir used by this member must be removed"}
[2024/07/10 15:15:01.332 +08:00] [WARN] [retry_interceptor.go:62] ["retrying of unary invoker failed"] [target=etcd-endpoints://0xc000b46000/127.0.0.1:57902] [attempt=0] [error="rpc error: code = Unavailable desc = etcdserver: server stopped"]
{"level":"info","ts":"2024-07-10T15:15:01.333138+0800","caller":"embed/etcd.go:375","msg":"closing etcd server","name":"test_etcd_1720595700879944000","data-dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/002","advertise-peer-urls":["http://127.0.0.1:57907"],"advertise-client-urls":["http://127.0.0.1:57908"]}
{"level":"warn","ts":"2024-07-10T15:15:01.333217+0800","caller":"embed/serve.go:173","msg":"stopping insecure grpc server due to error","error":"accept tcp 127.0.0.1:57908: use of closed network connection"}
[2024/07/10 15:15:01.333 +08:00] [WARN] [retry_interceptor.go:62] ["retrying of unary invoker failed"] [target=etcd-endpoints://0xc001c64000/127.0.0.1:57908] [attempt=0] [error="rpc error: code = Unavailable desc = error reading from server: EOF"]
2024/07/10 15:15:01 WARNING: [core] [Channel #17 SubChannel #18] grpc: addrConn.createTransport failed to connect to {Addr: "127.0.0.1:57908", ServerName: "127.0.0.1:57908", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:57908: connect: connection refused"
2024/07/10 15:15:01 WARNING: [core] [Channel #3 SubChannel #21] grpc: addrConn.createTransport failed to connect to {Addr: "127.0.0.1:57908", ServerName: "127.0.0.1:57908", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:57908: connect: connection refused"
{"level":"info","ts":"2024-07-10T15:15:01.33418+0800","caller":"membership/cluster.go:425","msg":"removed member","cluster-id":"7775bdc730413de5","local-member-id":"8195c4f470081d6c","removed-remote-peer-id":"8195c4f470081d6c","removed-remote-peer-urls":["http://127.0.0.1:57907"]}
2024/07/10 15:15:01 WARNING: [core] [Server #15] grpc: Server.processUnaryRPC failed to write status: connection error: desc = "transport is closing"
{"level":"info","ts":"2024-07-10T15:15:01.33431+0800","caller":"rafthttp/pipeline.go:86","msg":"stopped HTTP pipelining with remote peer","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"warn","ts":"2024-07-10T15:15:01.334339+0800","caller":"embed/serve.go:181","msg":"stopped insecure grpc server due to error","error":"accept tcp 127.0.0.1:57908: use of closed network connection"}
{"level":"info","ts":"2024-07-10T15:15:01.334362+0800","caller":"rafthttp/peer.go:333","msg":"stopping remote peer","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.334411+0800","caller":"etcdserver/server.go:1557","msg":"skipped leadership transfer; local server is not leader","local-member-id":"8195c4f470081d6c","current-leader-member-id":"517aa5d5512611cd"}
{"level":"warn","ts":"2024-07-10T15:15:01.334463+0800","caller":"rafthttp/stream.go:291","msg":"closed TCP streaming connection with remote peer","stream-writer-type":"stream MsgApp v2","remote-peer-id":"517aa5d5512611cd"}
{"level":"warn","ts":"2024-07-10T15:15:01.334503+0800","caller":"rafthttp/stream.go:301","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"stream MsgApp v2","remote-peer-id":"517aa5d5512611cd"}
{"level":"warn","ts":"2024-07-10T15:15:01.334567+0800","caller":"rafthttp/stream.go:291","msg":"closed TCP streaming connection with remote peer","stream-writer-type":"stream Message","remote-peer-id":"517aa5d5512611cd"}
{"level":"warn","ts":"2024-07-10T15:15:01.334596+0800","caller":"rafthttp/stream.go:301","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"stream Message","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.334646+0800","caller":"rafthttp/pipeline.go:86","msg":"stopped HTTP pipelining with remote peer","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.334688+0800","caller":"rafthttp/stream.go:459","msg":"stopped stream reader with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.334736+0800","caller":"rafthttp/stream.go:459","msg":"stopped stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"8195c4f470081d6c","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.33477+0800","caller":"rafthttp/peer.go:340","msg":"stopped remote peer","remote-peer-id":"517aa5d5512611cd"}
{"level":"info","ts":"2024-07-10T15:15:01.358291+0800","caller":"embed/etcd.go:584","msg":"stopping serving peer traffic","address":"127.0.0.1:57907"}
{"level":"info","ts":"2024-07-10T15:15:01.358488+0800","caller":"embed/etcd.go:591","msg":"stopped serving peer traffic","address":"127.0.0.1:57907"}
{"level":"info","ts":"2024-07-10T15:15:01.358535+0800","caller":"embed/etcd.go:379","msg":"closed etcd server","name":"test_etcd_1720595700879944000","data-dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/002","advertise-peer-urls":["http://127.0.0.1:57907"],"advertise-client-urls":["http://127.0.0.1:57908"]}
{"level":"info","ts":"2024-07-10T15:15:01.35859+0800","caller":"embed/etcd.go:375","msg":"closing etcd server","name":"test_etcd_1720595700092998000","data-dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/001","advertise-peer-urls":["http://127.0.0.1:57901"],"advertise-client-urls":["http://127.0.0.1:57902"]}
{"level":"warn","ts":"2024-07-10T15:15:01.358672+0800","caller":"embed/serve.go:173","msg":"stopping insecure grpc server due to error","error":"accept tcp 127.0.0.1:57902: use of closed network connection"}
{"level":"warn","ts":"2024-07-10T15:15:01.358812+0800","caller":"embed/serve.go:181","msg":"stopped insecure grpc server due to error","error":"accept tcp 127.0.0.1:57902: use of closed network connection"}
{"level":"info","ts":"2024-07-10T15:15:01.358883+0800","caller":"etcdserver/server.go:1570","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"517aa5d5512611cd","current-leader-member-id":"517aa5d5512611cd"}
2024/07/10 15:15:01 WARNING: [core] [Channel #3 SubChannel #4] grpc: addrConn.createTransport failed to connect to {Addr: "127.0.0.1:57902", ServerName: "127.0.0.1:57902", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:57902: connect: connection refused"
2024/07/10 15:15:01 WARNING: [core] [Channel #9 SubChannel #10] grpc: addrConn.createTransport failed to connect to {Addr: "127.0.0.1:57902", ServerName: "127.0.0.1:57902", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:57902: connect: connection refused"
{"level":"info","ts":"2024-07-10T15:15:01.382173+0800","caller":"embed/etcd.go:584","msg":"stopping serving peer traffic","address":"127.0.0.1:57901"}
{"level":"info","ts":"2024-07-10T15:15:01.382352+0800","caller":"embed/etcd.go:591","msg":"stopped serving peer traffic","address":"127.0.0.1:57901"}
{"level":"info","ts":"2024-07-10T15:15:01.382419+0800","caller":"embed/etcd.go:379","msg":"closed etcd server","name":"test_etcd_1720595700092998000","data-dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/001","advertise-peer-urls":["http://127.0.0.1:57901"],"advertise-client-urls":["http://127.0.0.1:57902"]}
[2024/07/10 15:15:01.382 +08:00] [WARN] [retry_interceptor.go:62] ["retrying of unary invoker failed"] [target=etcd-endpoints://0xc001c64000/127.0.0.1:57908] [attempt=1] [error="rpc error: code = Canceled desc = latest balancer error: last connection error: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:57908: connect: connection refused""]
[2024/07/10 15:15:01.382 +08:00] [WARN] [retry_interceptor.go:62] ["retrying of unary invoker failed"] [target=etcd-endpoints://0xc000b46000/127.0.0.1:57902] [attempt=0] [error="rpc error: code = Canceled desc = latest balancer error: last connection error: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:57902: connect: connection refused""]
[2024/07/10 15:15:01.382 +08:00] [WARN] [health_checker.go:194] ["etcd endpoint is unhealthy"] [endpoint=http://127.0.0.1:57908] [took=63.472375ms] [source=default-etcd-client]
[2024/07/10 15:15:01.382 +08:00] [INFO] [health_checker.go:299] ["evicted etcd endpoint found"] [endpoint=http://127.0.0.1:57908] [source=default-etcd-client]
{"level":"info","ts":"2024-07-10T15:15:01.382669+0800","caller":"embed/etcd.go:375","msg":"closing etcd server","name":"test_etcd_1720595700092998000","data-dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/001","advertise-peer-urls":["http://127.0.0.1:57901"],"advertise-client-urls":["http://127.0.0.1:57902"]}
[2024/07/10 15:15:01.382 +08:00] [INFO] [health_checker.go:137] ["update endpoints"] [num-change=2->1] [last-endpoints="[http://127.0.0.1:57902,http://127.0.0.1:57908]"] [endpoints="[http://127.0.0.1:57902]"] [source=default-etcd-client]
{"level":"info","ts":"2024-07-10T15:15:01.38274+0800","caller":"etcdserver/server.go:1570","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"517aa5d5512611cd","current-leader-member-id":"517aa5d5512611cd"}
[2024/07/10 15:15:01.382 +08:00] [ERROR] [health_checker.go:455] ["failed to list members"] [source=default-etcd-client] [error="[PD:etcd:ErrEtcdMemberList]context canceled: context canceled"] [errorVerbose="[PD:etcd:ErrEtcdMemberList]context canceled: context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/jiangxianjie/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByCause\n\t/Users/jiangxianjie/go/pkg/mod/github.com/pingcap/[email protected]/normalize.go:307\ngithub.com/tikv/pd/pkg/utils/etcdutil.ListEtcdMembers\n\t/Users/jiangxianjie/Code/okjiang/pd/pkg/utils/etcdutil/etcdutil.go:125\ngithub.com/tikv/pd/pkg/utils/etcdutil.(*healthChecker).syncURLs\n\t/Users/jiangxianjie/Code/okjiang/pd/pkg/utils/etcdutil/health_checker.go:453\ngithub.com/tikv/pd/pkg/utils/etcdutil.(*healthChecker).update\n\t/Users/jiangxianjie/Code/okjiang/pd/pkg/utils/etcdutil/health_checker.go:349\ngithub.com/tikv/pd/pkg/utils/etcdutil.(*healthChecker).syncer\n\t/Users/jiangxianjie/Code/okjiang/pd/pkg/utils/etcdutil/health_checker.go:100\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1197"] [stack="github.com/tikv/pd/pkg/utils/etcdutil.(*healthChecker).syncURLs\n\t/Users/jiangxianjie/Code/okjiang/pd/pkg/utils/etcdutil/health_checker.go:455\ngithub.com/tikv/pd/pkg/utils/etcdutil.(*healthChecker).update\n\t/Users/jiangxianjie/Code/okjiang/pd/pkg/utils/etcdutil/health_checker.go:349\ngithub.com/tikv/pd/pkg/utils/etcdutil.(*healthChecker).syncer\n\t/Users/jiangxianjie/Code/okjiang/pd/pkg/utils/etcdutil/health_checker.go:100"]
[2024/07/10 15:15:01.382 +08:00] [INFO] [health_checker.go:113] ["etcd client is closed, exit the health inspector goroutine"] [source=default-etcd-client]
{"level":"info","ts":"2024-07-10T15:15:01.382798+0800","caller":"embed/etcd.go:584","msg":"stopping serving peer traffic","address":"127.0.0.1:57901"}
[2024/07/10 15:15:01.382 +08:00] [WARN] [health_checker.go:351] ["no available etcd endpoint returned by etcd cluster"] [source=default-etcd-client]
[2024/07/10 15:15:01.382 +08:00] [INFO] [health_checker.go:96] ["etcd client is closed, exit the endpoint syncer goroutine"] [source=default-etcd-client]
{"level":"info","ts":"2024-07-10T15:15:01.382858+0800","caller":"embed/etcd.go:591","msg":"stopped serving peer traffic","address":"127.0.0.1:57901"}
{"level":"info","ts":"2024-07-10T15:15:01.382888+0800","caller":"embed/etcd.go:379","msg":"closed etcd server","name":"test_etcd_1720595700092998000","data-dir":"/var/folders/3f/xpw0q2k93p1cdcrrv_w_cglm0000gn/T/TestEtcdClientSync1085617163/001","advertise-peer-urls":["http://127.0.0.1:57901"],"advertise-client-urls":["http://127.0.0.1:57902"]}
--- FAIL: TestEtcdClientSync (1.29s)
/Users/jiangxianjie/Code/okjiang/pd/pkg/utils/etcdutil/etcdutil_test.go:199:
Error Trace: /Users/jiangxianjie/Code/okjiang/pd/pkg/utils/etcdutil/etcdutil_test.go:199
Error: Received unexpected error:
[PD:etcd:ErrEtcdMemberRemove]etcdserver: server stopped: etcdserver: server stopped
github.com/pingcap/errors.AddStack
/Users/jiangxianjie/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174
github.com/pingcap/errors.(*Error).GenWithStackByCause
/Users/jiangxianjie/go/pkg/mod/github.com/pingcap/[email protected]/normalize.go:307
github.com/tikv/pd/pkg/utils/etcdutil.RemoveEtcdMember
/Users/jiangxianjie/Code/okjiang/pd/pkg/utils/etcdutil/etcdutil.go:136
github.com/tikv/pd/pkg/utils/etcdutil.TestEtcdClientSync
/Users/jiangxianjie/Code/okjiang/pd/pkg/utils/etcdutil/etcdutil_test.go:198
testing.tRunner
/usr/local/go/src/testing/testing.go:1595
runtime.goexit
/usr/local/go/src/runtime/asm_arm64.s:1197
Test: TestEtcdClientSync
FAIL
FAIL github.com/tikv/pd/pkg/utils/etcdutil 4.488s
FAIL

Also, I did not replicate this issue on a Linux machine.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
type/ci The issue is related to CI.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

*: make TestEtcdClientSync stable rleungx/pd
3 participants
@lhy1024 @okJiang @rleungx