etcd
etcd copied to clipboard
Published
20 hours ago •
etcd-io
etcd-io
server: removed 'experimental' from warning-unary-request-duration flag
fixes https://github.com/etcd-io/etcd/issues/13783
Please read https://github.com/etcd-io/etcd/blob/main/CONTRIBUTING.md#contribution-flow.
Codecov Report
Merging #14414 (e3542b3) into main (22d930b) will decrease coverage by
0.18%. The diff coverage is100.00%.
@@ Coverage Diff @@
## main #14414 +/- ##
==========================================
- Coverage 75.66% 75.47% -0.19%
==========================================
Files 457 457
Lines 37320 37324 +4
==========================================
- Hits 28237 28172 -65
- Misses 7320 7369 +49
- Partials 1763 1783 +20
| Flag | Coverage Δ | |
|---|---|---|
| all | 75.47% <100.00%> (-0.19%) |
:arrow_down: |
Flags with carried forward coverage won't be shown. Click here to find out more.
| Impacted Files | Coverage Δ | |
|---|---|---|
| server/embed/config.go | 74.55% <100.00%> (ø) |
|
| server/embed/etcd.go | 78.10% <100.00%> (+0.12%) |
:arrow_up: |
| server/etcdmain/config.go | 86.40% <100.00%> (+0.05%) |
:arrow_up: |
| client/pkg/v3/tlsutil/tlsutil.go | 83.33% <0.00%> (-8.34%) |
:arrow_down: |
| raft/rafttest/node.go | 95.00% <0.00%> (-5.00%) |
:arrow_down: |
| client/v3/concurrency/session.go | 88.63% <0.00%> (-4.55%) |
:arrow_down: |
| server/etcdserver/txn/util.go | 75.47% <0.00%> (-3.78%) |
:arrow_down: |
| client/v3/leasing/txn.go | 88.09% <0.00%> (-3.18%) |
:arrow_down: |
| server/storage/mvcc/watchable_store.go | 89.85% <0.00%> (-2.90%) |
:arrow_down: |
| server/proxy/grpcproxy/watch.go | 93.64% <0.00%> (-2.90%) |
:arrow_down: |
| ... and 13 more |
:mega: We’re building smart automated test selection to slash your CI/CD build times. Learn more
The commit https://github.com/etcd-io/etcd/commit/2a26f7ae4c8617478380576c248636165c8bfbd2 , in which the flag was added, has never been cherry picked to release-3.5. It means that it's only included in main. Usually we shouldn't graduate a flag/feature until next minor release.
But for this flag, it doesn't change the existing functionality, instead it just makes the value (previously hard code as 300ms) configurable, and defaults to the same previous default value (300ms). So I think the "experimental" should be removed in the first place.
Based on the discussion in https://github.com/etcd-io/etcd/pull/14428, removing the experimental prefix is a breaking change, we can add --warning-unary-request-duration, but we may need to keep the experimental flag for at least one minor release.
@lavacat could you please resolve comment above so that we can merge this PR?
@ahrtr ready for review. Used your suggestions, added warning and duplicate test for experimental flag
It still has a flaw: if both flags are specified by users, then the experimental one is used. This isn't correct. The rough logic should be something like below,
initially set both to 0s by default
if both flags are specified (e.g., not zero) {
fail etcd
}
if "warning-unary-request-duration" is specified {
use warning-unary-request-duration
} else if "experimental-warning-unary-request-duration" is specified {
use experimental-warning-unary-request-duration
} else {
use the default 300ms
}
Failing e2e test is TestCtlV3Lock. Possibly related to https://github.com/etcd-io/etcd/issues/14763
2022-11-16T00:42:13.9909959Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"warn","ts":"2022-11-16T00:38:23.645Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_VERIFY=all"}
2022-11-16T00:42:13.9910706Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"warn","ts":"2022-11-16T00:38:23.645Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=amd64"}
2022-11-16T00:42:13.9912800Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.645Z","caller":"etcdmain/etcd.go:63","msg":"Running: ","args":["/home/runner/work/etcd/etcd/bin/etcd","--name","TestCtlV3Lock-test-0","--listen-client-urls","http://localhost:20000","--advertise-client-urls","http://localhost:20000","--listen-peer-urls","https://localhost:20001","--initial-advertise-peer-urls","https://localhost:20001","--initial-cluster-token","new","--data-dir","/tmp/TestCtlV3Lock3731017223/002","--snapshot-count","100000","--experimental-initial-corrupt-check","--peer-auto-tls","--initial-cluster","TestCtlV3Lock-test-0=https://localhost:20001","--initial-cluster-state","new"]}
2022-11-16T00:42:13.9913579Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.646Z","caller":"etcdmain/etcd.go:123","msg":"Initialize and start etcd server","data-dir":"/tmp/TestCtlV3Lock3731017223/002","dir-type":"empty"}
2022-11-16T00:42:13.9914531Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.647Z","caller":"embed/etcd.go:121","msg":"configuring peer listeners","listen-peer-urls":["https://localhost:20001"]}
2022-11-16T00:42:13.9915542Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"warn","ts":"2022-11-16T00:38:23.647Z","caller":"transport/listener.go:264","msg":"automatically generate certificates","certificate-validity-bound-not-after":"2023-11-16T00:38:23.647Z"}
2022-11-16T00:42:13.9916295Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.677Z","caller":"transport/listener.go:313","msg":"created cert file","path":"/tmp/TestCtlV3Lock3731017223/002/fixtures/peer/cert.pem"}
2022-11-16T00:42:13.9917030Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.677Z","caller":"transport/listener.go:334","msg":"created key file","path":"/tmp/TestCtlV3Lock3731017223/002/fixtures/peer/key.pem"}
2022-11-16T00:42:13.9918579Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.677Z","caller":"embed/etcd.go:503","msg":"starting with peer TLS","tls-info":"cert = /tmp/TestCtlV3Lock3731017223/002/fixtures/peer/cert.pem, key = /tmp/TestCtlV3Lock3731017223/002/fixtures/peer/key.pem, client-cert=/tmp/TestCtlV3Lock3731017223/002/fixtures/peer/cert.pem, client-key=/tmp/TestCtlV3Lock3731017223/002/fixtures/peer/key.pem, trusted-ca = , client-cert-auth = false, crl-file = ","cipher-suites":[]}
2022-11-16T00:42:13.9919314Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.680Z","caller":"embed/etcd.go:129","msg":"configuring client listeners","listen-client-urls":["http://localhost:20000"]}
2022-11-16T00:42:13.9924677Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.681Z","caller":"embed/etcd.go:309","msg":"starting an etcd server","etcd-version":"3.6.0-alpha.0","git-sha":"aa12a07","go-version":"go1.19.3","go-os":"linux","go-arch":"amd64","max-cpu-set":2,"max-cpu-available":2,"member-initialized":false,"name":"TestCtlV3Lock-test-0","data-dir":"/tmp/TestCtlV3Lock3731017223/002","wal-dir":"","wal-dir-dedicated":"","member-dir":"/tmp/TestCtlV3Lock3731017223/002/member","force-new-cluster":false,"heartbeat-interval":"100ms","election-timeout":"1s","wait-cluster-ready-timeout":"5s","initial-election-tick-advance":true,"snapshot-count":100000,"max-wals":5,"max-snapshots":5,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["https://localhost:20001"],"listen-peer-urls":["https://localhost:20001"],"advertise-client-urls":["http://localhost:20000"],"listen-client-urls":["http://localhost:20000"],"listen-metrics-urls":[],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"TestCtlV3Lock-test-0=https://localhost:20001","initial-cluster-state":"new","initial-cluster-token":"new","quota-backend-bytes":2147483648,"max-request-bytes":1572864,"max-concurrent-streams":4294967295,"pre-vote":true,"initial-corrupt-check":true,"corrupt-check-time-interval":"0s","compact-check-time-enabled":false,"compact-check-time-interval":"1m0s","auto-compaction-mode":"periodic","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":"","discovery-token":"","discovery-endpoints":"","discovery-dial-timeout":"2s","discovery-request-timeout":"5s","discovery-keepalive-time":"2s","discovery-keepalive-timeout":"6s","discovery-insecure-transport":true,"discovery-insecure-skip-tls-verify":false,"discovery-cert":"","discovery-key":"","discovery-cacert":"","discovery-user":"","downgrade-check-interval":"5s","max-learners":1}
2022-11-16T00:42:13.9925465Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.686Z","caller":"storage/backend.go:81","msg":"opened backend db","path":"/tmp/TestCtlV3Lock3731017223/002/member/snap/db","took":"1.452015ms"}
2022-11-16T00:42:13.9926465Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.689Z","caller":"etcdserver/bootstrap.go:499","msg":"starting local member","local-member-id":"a8f3458387986d","cluster-id":"34c21a2d427db393"}
2022-11-16T00:42:13.9927146Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.689Z","logger":"raft","caller":"raft/raft.go:1697","msg":"a8f3458387986d switched to configuration voters=()"}
2022-11-16T00:42:13.9927781Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.689Z","logger":"raft","caller":"raft/raft.go:728","msg":"a8f3458387986d became follower at term 0"}
2022-11-16T00:42:13.9928516Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.689Z","logger":"raft","caller":"raft/raft.go:382","msg":"newRaft a8f3458387986d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"}
2022-11-16T00:42:13.9929265Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.689Z","logger":"raft","caller":"raft/raft.go:728","msg":"a8f3458387986d became follower at term 1"}
2022-11-16T00:42:13.9929946Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.689Z","logger":"raft","caller":"raft/raft.go:1697","msg":"a8f3458387986d switched to configuration voters=(47555275972384877)"}
2022-11-16T00:42:13.9930803Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"warn","ts":"2022-11-16T00:38:23.691Z","caller":"auth/store.go:1119","msg":"simple token is not cryptographically signed"}
2022-11-16T00:42:13.9931472Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.692Z","caller":"mvcc/kvstore.go:385","msg":"kvstore restored","current-rev":1}
2022-11-16T00:42:13.9932271Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.693Z","caller":"storage/quota.go:93","msg":"enabled backend quota with default value","quota-name":"v3-applier","quota-size-bytes":2147483648,"quota-size":"2.1 GB"}
2022-11-16T00:42:13.9933102Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.698Z","caller":"etcdserver/server.go:581","msg":"starting etcd server","local-member-id":"a8f3458387986d","local-server-version":"3.6.0-alpha.0","cluster-version":"to_be_decided"}
2022-11-16T00:42:13.9934375Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.699Z","caller":"embed/etcd.go:278","msg":"now serving peer/client/metrics","local-member-id":"a8f3458387986d","initial-advertise-peer-urls":["https://localhost:20001"],"listen-peer-urls":["https://localhost:20001"],"advertise-client-urls":["http://localhost:20000"],"listen-client-urls":["http://localhost:20000"],"listen-metrics-urls":[]}
2022-11-16T00:42:13.9934988Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.699Z","caller":"embed/etcd.go:597","msg":"serving peer traffic","address":"127.0.0.1:20001"}
2022-11-16T00:42:13.9935748Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.699Z","caller":"embed/etcd.go:569","msg":"cmux::serve","address":"127.0.0.1:20001"}
2022-11-16T00:42:13.9936534Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.699Z","caller":"fileutil/purge.go:44","msg":"started to purge file","dir":"/tmp/TestCtlV3Lock3731017223/002/member/snap","suffix":"snap.db","max":5,"interval":"30s"}
2022-11-16T00:42:13.9937421Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.699Z","caller":"fileutil/purge.go:44","msg":"started to purge file","dir":"/tmp/TestCtlV3Lock3731017223/002/member/snap","suffix":"snap","max":5,"interval":"30s"}
2022-11-16T00:42:13.9938225Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.699Z","caller":"fileutil/purge.go:44","msg":"started to purge file","dir":"/tmp/TestCtlV3Lock3731017223/002/member/wal","suffix":"wal","max":5,"interval":"30s"}
2022-11-16T00:42:13.9938910Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.699Z","logger":"raft","caller":"raft/raft.go:1697","msg":"a8f3458387986d switched to configuration voters=(47555275972384877)"}
2022-11-16T00:42:13.9939932Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.699Z","caller":"membership/cluster.go:404","msg":"added member","cluster-id":"34c21a2d427db393","local-member-id":"a8f3458387986d","added-peer-id":"a8f3458387986d","added-peer-peer-urls":["https://localhost:20001"],"added-peer-is-learner":false}
2022-11-16T00:42:13.9940993Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.699Z","caller":"etcdserver/server.go:466","msg":"started as single-node; fast-forwarding election ticks","local-member-id":"a8f3458387986d","forward-ticks":9,"forward-duration":"900ms","election-ticks":10,"election-timeout":"1s"}
2022-11-16T00:42:13.9941642Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.990Z","logger":"raft","caller":"raft/raft.go:819","msg":"a8f3458387986d is starting a new election at term 1"}
2022-11-16T00:42:13.9942264Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.990Z","logger":"raft","caller":"raft/raft.go:757","msg":"a8f3458387986d became pre-candidate at term 1"}
2022-11-16T00:42:13.9942959Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.990Z","logger":"raft","caller":"raft/raft.go:879","msg":"a8f3458387986d received MsgPreVoteResp from a8f3458387986d at term 1"}
2022-11-16T00:42:13.9943910Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.990Z","logger":"raft","caller":"raft/raft.go:741","msg":"a8f3458387986d became candidate at term 2"}
2022-11-16T00:42:13.9944726Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.990Z","logger":"raft","caller":"raft/raft.go:879","msg":"a8f3458387986d received MsgVoteResp from a8f3458387986d at term 2"}
2022-11-16T00:42:13.9945321Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.990Z","logger":"raft","caller":"raft/raft.go:797","msg":"a8f3458387986d became leader at term 2"}
2022-11-16T00:42:13.9945983Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.990Z","logger":"raft","caller":"raft/node.go:330","msg":"raft.node: a8f3458387986d elected leader a8f3458387986d at term 2"}
2022-11-16T00:42:13.9946651Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.991Z","caller":"etcdserver/server.go:2284","msg":"setting up initial cluster version using v3 API","cluster-version":"3.6"}
2022-11-16T00:42:13.9947434Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.991Z","caller":"membership/cluster.go:547","msg":"set initial cluster version","cluster-id":"34c21a2d427db393","local-member-id":"a8f3458387986d","cluster-version":"3.6"}
2022-11-16T00:42:13.9948580Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.992Z","caller":"etcdserver/server.go:1728","msg":"published local member to cluster through raft","local-member-id":"a8f3458387986d","local-member-attributes":"{Name:TestCtlV3Lock-test-0 ClientURLs:[http://localhost:20000]}","cluster-id":"34c21a2d427db393","publish-timeout":"7s"}
2022-11-16T00:42:13.9949238Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.992Z","caller":"api/capability.go:76","msg":"enabled capabilities for version","cluster-version":"3.6"}
2022-11-16T00:42:13.9949858Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.992Z","caller":"etcdserver/server.go:2304","msg":"cluster version is updated","cluster-version":"3.6"}
2022-11-16T00:42:13.9951371Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.992Z","caller":"embed/serve.go:110","msg":"ready to serve client requests"}
2022-11-16T00:42:13.9951958Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.992Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"}
2022-11-16T00:42:13.9952761Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.992Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"}
2022-11-16T00:42:13.9953539Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.992Z","caller":"version/monitor.go:115","msg":"cluster version differs from storage version.","cluster-version":"3.6.0","storage-version":"3.5.0"}
2022-11-16T00:42:13.9954390Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.992Z","caller":"schema/migration.go:64","msg":"updated storage version","new-storage-version":"3.6.0"}
2022-11-16T00:42:13.9955103Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:23.996Z","caller":"embed/serve.go:162","msg":"serving client traffic insecurely; this is strongly discouraged!","address":"127.0.0.1:20000"}
2022-11-16T00:42:13.9955687Z /home/runner/work/etcd/etcd/bin/etcdctl (/home/runner/work/etcd/etcd/bin/etcdctl_--endpoints=http://localhost:20000_--dial-timeout=7s_lock_a) (15415): a/186d847ddf66c905
2022-11-16T00:42:13.9956211Z /home/runner/work/etcd/etcd/bin/etcdctl (/home/runner/work/etcd/etcd/bin/etcdctl_--endpoints=http://localhost:20000_--dial-timeout=7s_lock_a) (15415):
2022-11-16T00:42:13.9956789Z /home/runner/work/etcd/etcd/bin/etcdctl (/home/runner/work/etcd/etcd/bin/etcdctl_--endpoints=http://localhost:20000_--dial-timeout=7s_lock_a) (15422): Error: context canceled
2022-11-16T00:42:13.9957334Z /home/runner/work/etcd/etcd/bin/etcdctl (/home/runner/work/etcd/etcd/bin/etcdctl_--endpoints=http://localhost:20000_--dial-timeout=7s_lock_a) (15429): a/186d847ddf66c90d
2022-11-16T00:42:13.9957854Z /home/runner/work/etcd/etcd/bin/etcdctl (/home/runner/work/etcd/etcd/bin/etcdctl_--endpoints=http://localhost:20000_--dial-timeout=7s_lock_a) (15429):
2022-11-16T00:42:13.9958509Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:24.299Z","caller":"osutil/interrupt_unix.go:66","msg":"received signal; shutting down","signal":"terminated"}
2022-11-16T00:42:13.9959529Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:24.299Z","caller":"embed/etcd.go:392","msg":"closing etcd server","name":"TestCtlV3Lock-test-0","data-dir":"/tmp/TestCtlV3Lock3731017223/002","advertise-peer-urls":["https://localhost:20001"],"advertise-client-urls":["http://localhost:20000"]}
2022-11-16T00:42:13.9960272Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"warn","ts":"2022-11-16T00:38:24.299Z","caller":"embed/serve.go:120","msg":"stopping grpc server due to error","error":"accept tcp 127.0.0.1:20000: use of closed network connection"}
2022-11-16T00:42:13.9961610Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"error","ts":"2022-11-16T00:38:24.299Z","caller":"embed/etcd.go:773","msg":"setting up serving from embedded etcd failed.","error":"mux: server closed","stacktrace":"go.etcd.io/etcd/server/v3/embed.(*Etcd).errHandler\n\t/home/runner/work/etcd/etcd/server/embed/etcd.go:773\ngo.etcd.io/etcd/server/v3/embed.(*serveCtx).serve.func2\n\t/home/runner/work/etcd/etcd/server/embed/serve.go:137"}
2022-11-16T00:42:13.9962888Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"error","ts":"2022-11-16T00:38:24.299Z","caller":"embed/etcd.go:773","msg":"setting up serving from embedded etcd failed.","error":"http: Server closed","stacktrace":"go.etcd.io/etcd/server/v3/embed.(*Etcd).errHandler\n\t/home/runner/work/etcd/etcd/server/embed/etcd.go:773\ngo.etcd.io/etcd/server/v3/embed.(*serveCtx).serve.func3\n\t/home/runner/work/etcd/etcd/server/embed/serve.go:159"}
2022-11-16T00:42:13.9963908Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:24.299Z","caller":"etcdserver/server.go:1216","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"a8f3458387986d","current-leader-member-id":"a8f3458387986d"}
2022-11-16T00:42:13.9964713Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"warn","ts":"2022-11-16T00:38:24.299Z","caller":"embed/serve.go:122","msg":"stopped grpc server due to error","error":"accept tcp 127.0.0.1:20000: use of closed network connection"}
2022-11-16T00:42:13.9966033Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"error","ts":"2022-11-16T00:38:24.299Z","caller":"embed/etcd.go:773","msg":"setting up serving from embedded etcd failed.","error":"accept tcp 127.0.0.1:20000: use of closed network connection","stacktrace":"go.etcd.io/etcd/server/v3/embed.(*Etcd).errHandler\n\t/home/runner/work/etcd/etcd/server/embed/etcd.go:773\ngo.etcd.io/etcd/server/v3/embed.(*Etcd).serveClients.func1\n\t/home/runner/work/etcd/etcd/server/embed/etcd.go:730"}
2022-11-16T00:42:13.9966656Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:24.301Z","caller":"embed/etcd.go:579","msg":"stopping serving peer traffic","address":"127.0.0.1:20001"}
2022-11-16T00:42:13.9967963Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"error","ts":"2022-11-16T00:38:24.301Z","caller":"embed/etcd.go:773","msg":"setting up serving from embedded etcd failed.","error":"accept tcp 127.0.0.1:20001: use of closed network connection","stacktrace":"go.etcd.io/etcd/server/v3/embed.(*Etcd).errHandler\n\t/home/runner/work/etcd/etcd/server/embed/etcd.go:773\ngo.etcd.io/etcd/server/v3/embed.(*Etcd).servePeers.func3\n\t/home/runner/work/etcd/etcd/server/embed/etcd.go:601"}
2022-11-16T00:42:13.9968579Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:24.301Z","caller":"embed/etcd.go:584","msg":"stopped serving peer traffic","address":"127.0.0.1:20001"}
2022-11-16T00:42:13.9969563Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:24.301Z","caller":"embed/etcd.go:394","msg":"closed etcd server","name":"TestCtlV3Lock-test-0","data-dir":"/tmp/TestCtlV3Lock3731017223/002","advertise-peer-urls":["https://localhost:20001"],"advertise-client-urls":["http://localhost:20000"]}
2022-11-16T00:42:13.9971104Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:24.301Z","caller":"verify/verify.go:56","msg":"verification of persisted state","data-dir":"/tmp/TestCtlV3Lock3731017223/002"}
2022-11-16T00:42:14.0078937Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:24.302Z","caller":"verify/verify.go:124","msg":"verification: consistentIndex OK","backend-consistent-index":12,"hardstate-commit":12}
2022-11-16T00:42:14.0080211Z /home/runner/work/etcd/etcd/bin/etcd (TestCtlV3Lock-test-0) (15408): {"level":"info","ts":"2022-11-16T00:38:24.302Z","caller":"verify/verify.go:67","msg":"verification of persisted state successful","data-dir":"/tmp/TestCtlV3Lock3731017223/002"}
2022-11-16T00:42:14.0080474Z --- FAIL: TestCtlV3Lock (1.71s)
2022-11-16T00:42:14.0080830Z before.go:35: Changing working directory to: /tmp/TestCtlV3Lock3731017223/001
2022-11-16T00:42:14.0081364Z logger.go:130: 2022-11-16T00:38:23.627Z INFO starting server... {"name": "TestCtlV3Lock-test-0"}
2022-11-16T00:42:14.0099752Z logger.go:130: 2022-11-16T00:38:23.627Z INFO spawning process {"args": ["/home/runner/work/etcd/etcd/bin/etcd", "--name", "TestCtlV3Lock-test-0", "--listen-client-urls", "http://localhost:20000", "--advertise-client-urls", "http://localhost:20000", "--listen-peer-urls", "https://localhost:20001", "--initial-advertise-peer-urls", "https://localhost:20001", "--initial-cluster-token", "new", "--data-dir", "/tmp/TestCtlV3Lock3731017223/002", "--snapshot-count", "100000", "--experimental-initial-corrupt-check", "--peer-auto-tls", "--initial-cluster", "TestCtlV3Lock-test-0=https://localhost:20001", "--initial-cluster-state", "new"], "working-dir": "/tmp/TestCtlV3Lock3731017223/001", "name": "TestCtlV3Lock-test-0", "environment-variables": ["ETCD_VERIFY=all", "EXPECT_DEBUG=true", "PATH=/opt/hostedtoolcache/go/1.19.3/x64/bin:/home/runner/go/bin:/opt/hostedtoolcache/go/1.19.3/x64/bin:/home/runner/.local/bin:/opt/pipx_bin:/home/runner/.cargo/bin:/home/runner/.config/composer/vendor/bin:/usr/local/.ghcup/bin:/home/runner/.dotnet/tools:/snap/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin", "ETCD_UNSUPPORTED_ARCH=amd64"]}
2022-11-16T00:42:14.0101098Z logger.go:130: 2022-11-16T00:38:23.997Z INFO started server. {"name": "TestCtlV3Lock-test-0", "pid": 15408}
2022-11-16T00:42:14.0101479Z ctl_v3_test.go:261: ---testFunc logic DONE
2022-11-16T00:42:14.0101703Z ctl_v3_test.go:272: closing test cluster...
2022-11-16T00:42:14.0102204Z logger.go:130: 2022-11-16T00:38:24.299Z INFO stopping server... {"name": "TestCtlV3Lock-test-0"}
2022-11-16T00:42:14.0102697Z logger.go:130: 2022-11-16T00:38:24.304Z INFO stopped server. {"name": "TestCtlV3Lock-test-0"}
2022-11-16T00:42:14.0103431Z logger.go:130: 2022-11-16T00:38:24.304Z INFO closing test cluster...
2022-11-16T00:42:14.0103957Z logger.go:130: 2022-11-16T00:38:24.304Z INFO stopping server... {"name": "TestCtlV3Lock-test-0"}
2022-11-16T00:42:14.0104430Z logger.go:130: 2022-11-16T00:38:24.304Z INFO closing server... {"name": "TestCtlV3Lock-test-0"}
2022-11-16T00:42:14.0104886Z logger.go:130: 2022-11-16T00:38:24.304Z INFO stopping server... {"name": "TestCtlV3Lock-test-0"}
2022-11-16T00:42:14.0105425Z logger.go:130: 2022-11-16T00:38:24.304Z INFO removing directory {"data-dir": "/tmp/TestCtlV3Lock3731017223/002"}
2022-11-16T00:42:14.0105790Z logger.go:130: 2022-11-16T00:38:24.304Z INFO closed test cluster.
2022-11-16T00:42:14.0106012Z ctl_v3_test.go:276: closed test cluster...
2022-11-16T00:42:14.0106231Z leak.go:118: Test appears to have leaked :
2022-11-16T00:42:14.0106564Z syscall.Syscall(0x4a8365?, 0x1603ce0?, 0x4a8532?, 0x7ffff800000?)
2022-11-16T00:42:14.0107003Z /opt/hostedtoolcache/go/1.19.3/x64/src/syscall/syscall_linux.go:68 +0x27
2022-11-16T00:42:14.0107342Z syscall.read(0xc00033db60?, {0xc0002a5000?, 0x1?, 0x7fe4eb45f5b8?})
2022-11-16T00:42:14.0107784Z /opt/hostedtoolcache/go/1.19.3/x64/src/syscall/zsyscall_linux_amd64.go:696 +0x45
2022-11-16T00:42:14.0107945Z syscall.Read(...)
2022-11-16T00:42:14.0108348Z /opt/hostedtoolcache/go/1.19.3/x64/src/syscall/syscall_unix.go:183
2022-11-16T00:42:14.0108588Z internal/poll.ignoringEINTRIO(...)
2022-11-16T00:42:14.0109002Z /opt/hostedtoolcache/go/1.19.3/x64/src/internal/poll/fd_unix.go:794
2022-11-16T00:42:14.0109359Z internal/poll.(*FD).Read(0xc00033db60?, {0xc0002a5000?, 0x1000?, 0x1000?})
2022-11-16T00:42:14.0109799Z /opt/hostedtoolcache/go/1.19.3/x64/src/internal/poll/fd_unix.go:163 +0x285
2022-11-16T00:42:14.0109967Z os.(*File).read(...)
2022-11-16T00:42:14.0110451Z /opt/hostedtoolcache/go/1.19.3/x64/src/os/file_posix.go:31
2022-11-16T00:42:14.0110818Z os.(*File).Read(0xc000122220, {0xc0002a5000?, 0xc000076c48?, 0x4f007e?})
2022-11-16T00:42:14.0111197Z /opt/hostedtoolcache/go/1.19.3/x64/src/os/file.go:118 +0x5e
2022-11-16T00:42:14.0111418Z bufio.(*Reader).fill(0xc000076f50)
2022-11-16T00:42:14.0111808Z /opt/hostedtoolcache/go/1.19.3/x64/src/bufio/bufio.go:106 +0xff
2022-11-16T00:42:14.0112073Z bufio.(*Reader).ReadSlice(0xc000076f50, 0x38?)
2022-11-16T00:42:14.0112462Z /opt/hostedtoolcache/go/1.19.3/x64/src/bufio/bufio.go:372 +0x2f
2022-11-16T00:42:14.0112763Z bufio.(*Reader).collectFragments(0xc000037140?, 0x11?)
2022-11-16T00:42:14.0113133Z /opt/hostedtoolcache/go/1.19.3/x64/src/bufio/bufio.go:447 +0x71
2022-11-16T00:42:14.0113477Z bufio.(*Reader).ReadString(0xe55211?, 0xc?)
2022-11-16T00:42:14.0113870Z /opt/hostedtoolcache/go/1.19.3/x64/src/bufio/bufio.go:495 +0x2b
2022-11-16T00:42:14.0114310Z go.etcd.io/etcd/pkg/v3/expect.(*ExpectProcess).tryReadNextLine(0xc00001e3c0, 0xb67fa2?)
2022-11-16T00:42:14.0114682Z /home/runner/work/etcd/etcd/pkg/expect/expect.go:124 +0x79
2022-11-16T00:42:14.0115034Z go.etcd.io/etcd/pkg/v3/expect.(*ExpectProcess).read(0xc00001e3c0)
2022-11-16T00:42:14.0115413Z /home/runner/work/etcd/etcd/pkg/expect/expect.go:115 +0x1c8
2022-11-16T00:42:14.0115742Z created by go.etcd.io/etcd/pkg/v3/expect.NewExpectWithEnv
2022-11-16T00:42:14.0116094Z /home/runner/work/etcd/etcd/pkg/expect/expect.go:79 +0x245
2022-11-16T00:42:14.0116196Z
2022-11-16T00:42:14.0116619Z syscall.Syscall6(0xc0000615a0?, 0x4b34f4?, 0xe55211?, 0xc?, 0xc000061698?, 0xb66959?, 0xe55211?)
2022-11-16T00:42:14.0117049Z /opt/hostedtoolcache/go/1.19.3/x64/src/syscall/syscall_linux.go:90 +0x36
2022-11-16T00:42:14.0117334Z os.(*Process).blockUntilWaitable(0xc0000410e0)
2022-11-16T00:42:14.0117736Z /opt/hostedtoolcache/go/1.19.3/x64/src/os/wait_waitid.go:32 +0x87
2022-11-16T00:42:14.0117952Z os.(*Process).wait(0xc0000410e0)
2022-11-16T00:42:14.0118342Z /opt/hostedtoolcache/go/1.19.3/x64/src/os/exec_unix.go:22 +0x28
2022-11-16T00:42:14.0118509Z os.(*Process).Wait(...)
2022-11-16T00:42:14.0118863Z /opt/hostedtoolcache/go/1.19.3/x64/src/os/exec.go:132
2022-11-16T00:42:14.0119244Z go.etcd.io/etcd/pkg/v3/expect.(*ExpectProcess).waitProcess(0xc00001e3c0)
2022-11-16T00:42:14.0119617Z /home/runner/work/etcd/etcd/pkg/expect/expect.go:271 +0x5b
2022-11-16T00:42:14.0120013Z go.etcd.io/etcd/pkg/v3/expect.(*ExpectProcess).waitSaveExitErr(0xc00001e3c0)
2022-11-16T00:42:14.0120379Z /home/runner/work/etcd/etcd/pkg/expect/expect.go:143 +0x59
2022-11-16T00:42:14.0120708Z created by go.etcd.io/etcd/pkg/v3/expect.NewExpectWithEnv
2022-11-16T00:42:14.0121080Z /home/runner/work/etcd/etcd/pkg/expect/expect.go:80 +0x285