[3.5] Backport fix(server/embed) enforce non-empty client TLS if scheme is https/unixs

[jmhbnz]

This was not a straightforward backport so needs a closer review than normal.

Backports a657f06, 22f20a8, 497f1a4 and 3e86af6 from #18186.

Also backports required tests/e2e/utils.go elements of 4c77726 from #17661.

cc @serathius, @ahrtr, @ivanvc

[ivanvc]

/retest

[jmhbnz]

e2e test failures are not a flake, failing test is the one we are attempting to backport TestEtcdListenMetricsURLsWithMissingClientTLSInfo.

The interesting thing is the test is supposed to be checking for string client TLS key/cert (--cert-file, --key-file) must be provided for metrics secure url from process output but that exact line is present in the logs below.

Will keep looking, @ahrtr if you can see what is going wrong please let me know.

 100884 2024-07-06T12:05:12.9656823Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.287291Z","caller":"etcdmain/etcd.go:73","msg":"Running:                                                                                                                                           
        ","args":["/home/runner/work/etcd/etcd/bin/etcd","--name","e0","--data-dir","/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001","--listen-client-urls","http://localhost:20000","--advertise-client-urls","http://localhost:20000","--initial-advertise-peer-urls","https://localhost:20001","--li\
        sten-peer-urls","https://localhost:20001","--initial-cluster","e0=https://localhost:20001","--listen-metrics-urls","https://localhost:20002","--peer-cert-file","/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001/3720725653.crt","--peer-key-file","/tmp/TestEtcdListenMetricsURLsWithMissingCli\
        entTLSInfo814463894/001/855974323.key.insecure","--peer-trusted-ca-file","/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001/2557539066.crt","--peer-client-cert-auth"]}                                                                                                                            
 100885 2024-07-06T12:05:12.9658316Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"warn","ts":"2024-07-06T12:00:36.287412Z","caller":"etcdmain/etcd.go:446","msg":"found invalid file under data                                                                                                                     
        directory","filename":"2557539066.crt","data-dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001"}                                                                                                                                                                                             
 100886 2024-07-06T12:05:12.9659673Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"warn","ts":"2024-07-06T12:00:36.287431Z","caller":"etcdmain/etcd.go:446","msg":"found invalid file under data                                                                                                                     
        directory","filename":"3720725653.crt","data-dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001"}                                                                                                                                                                                             
 100887 2024-07-06T12:05:12.9661156Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"warn","ts":"2024-07-06T12:00:36.287448Z","caller":"etcdmain/etcd.go:446","msg":"found invalid file under data                                                                                                                     
        directory","filename":"855974323.key.insecure","data-dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001"}                                                                                                                                                                                     
 100888 2024-07-06T12:05:12.9662332Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"warn","ts":"2024-07-06T12:00:36.287494Z","caller":"embed/config.go:687","msg":"Running http and grpc server on single port. This is not recommended for production."}                                                             
 100889 2024-07-06T12:05:12.9663265Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.287533Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["https://localhost:20001"]}                                                                          
 100890 2024-07-06T12:05:12.9665881Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.287613Z","caller":"embed/etcd.go:496","msg":"starting with peer TLS","tls-info":"cert = /tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001/3720725653.crt, key =                 
        /tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001/855974323.key.insecure, client-cert=, client-key=, trusted-ca = /tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001/2557539066.crt, client-cert-auth = true, crl-file = ","cipher-suites":[]}                                    
 100891 2024-07-06T12:05:12.9666827Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.289257Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["http://localhost:20000"]}                                                                       
 100892 2024-07-06T12:05:12.9674001Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.28952Z","caller":"embed/etcd.go:310","msg":"starting an etcd                                                                                                                                      
        server","etcd-version":"3.5.14","git-sha":"2397425","go-version":"go1.21.12","go-os":"linux","go-arch":"386","max-cpu-set":4,"max-cpu-available":4,"member-initialized":false,"name":"e0","data-dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001","wal-dir":"","wal-dir-dedicated":"","memb\
        er-dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/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-p\
        eer-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":["https://localhost:20002"],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"e0=https://localhos\
        t:20001","initial-cluster-state":"new","initial-cluster-token":"etcd-cluster","quota-backend-bytes":2147483648,"max-request-bytes":1572864,"max-concurrent-streams":4294967295,"pre-vote":true,"initial-corrupt-check":false,"corrupt-check-time-interval":"0s","compact-check-time-enabled":false,"compact-check-ti\
        me-interval":"1m0s","auto-compaction-mode":"periodic","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":"","downgrade-check-interval":"5s"}                                                                                                                      
 100893 2024-07-06T12:05:12.9675851Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"warn","ts":"2024-07-06T12:00:36.289598Z","caller":"fileutil/fileutil.go:53","msg":"check file permission","error":"directory \"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001\" exist, but the permission    
        is \"drwxr-xr-x\". The recommended permission is \"-rwx------\" to prevent possible unprivileged access to the data"}                                                                                                                                                                                                
 100894 2024-07-06T12:05:12.9677120Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.291015Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001/member/snap/db","took":"1.063242ms"}           
 100895 2024-07-06T12:05:12.9678131Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.293428Z","caller":"etcdserver/raft.go:495","msg":"starting local member","local-member-id":"320a84688a8d3d46","cluster-id":"7d9f2c162a40ecd2"}                                                    
 100896 2024-07-06T12:05:12.9679116Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.29348Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"320a84688a8d3d46 switched to configuration voters=()"}                                                                        
 100897 2024-07-06T12:05:12.9680145Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.29351Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"320a84688a8d3d46 became follower at term 0"}                                                                                  
 100898 2024-07-06T12:05:12.9681243Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.293534Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 320a84688a8d3d46 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"}                            
 100899 2024-07-06T12:05:12.9682114Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.293554Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"320a84688a8d3d46 became follower at term 1"}                                                                                 
 100900 2024-07-06T12:05:12.9683116Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.293619Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"320a84688a8d3d46 switched to configuration voters=(3605840036199480646)"}                                                    
 100901 2024-07-06T12:05:12.9683905Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"warn","ts":"2024-07-06T12:00:36.29504Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"}                                                                                                       
 100902 2024-07-06T12:05:12.9684651Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.295581Z","caller":"mvcc/kvstore.go:418","msg":"kvstore restored","current-rev":1}                                                                                                                 
 100903 2024-07-06T12:05:12.9685786Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.296015Z","caller":"etcdserver/quota.go:94","msg":"enabled backend quota with default value","quota-name":"v3-applier","quota-size-bytes":2147483648,"quota-size":"2.1 GB"}                        
 100904 2024-07-06T12:05:12.9686960Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.298149Z","caller":"etcdserver/server.go:867","msg":"starting etcd server","local-member-id":"320a84688a8d3d46","local-server-version":"3.5.14","cluster-version":"to_be_decided"}                 
 100905 2024-07-06T12:05:12.9688399Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.298251Z","caller":"etcdserver/server.go:751","msg":"started as single-node; fast-forwarding election                                                                                              
        ticks","local-member-id":"320a84688a8d3d46","forward-ticks":9,"forward-duration":"900ms","election-ticks":10,"election-timeout":"1s"}                                                                                                                                                                                
 100906 2024-07-06T12:05:12.9689750Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.298369Z","caller":"fileutil/purge.go:50","msg":"started to purge                                                                                                                                  
        file","dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001/member/snap","suffix":"snap.db","max":5,"interval":"30s"}                                                                                                                                                                           
 100907 2024-07-06T12:05:12.9691090Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.298427Z","caller":"fileutil/purge.go:50","msg":"started to purge                                                                                                                                  
        file","dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001/member/snap","suffix":"snap","max":5,"interval":"30s"}                                                                                                                                                                              
 100908 2024-07-06T12:05:12.9692414Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.298464Z","caller":"fileutil/purge.go:50","msg":"started to purge                                                                                                                                  
        file","dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001/member/wal","suffix":"wal","max":5,"interval":"30s"}                                                                                                                                                                                
 100909 2024-07-06T12:05:12.9693417Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.298837Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"320a84688a8d3d46 switched to configuration voters=(3605840036199480646)"}                                                    
 100910 2024-07-06T12:05:12.9694799Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.299015Z","caller":"membership/cluster.go:421","msg":"added                                                                                                                                        
        member","cluster-id":"7d9f2c162a40ecd2","local-member-id":"320a84688a8d3d46","added-peer-id":"320a84688a8d3d46","added-peer-peer-urls":["https://localhost:20001"]}                                                                                                                                                  
 100911 2024-07-06T12:05:12.9695742Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.299356Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"}                                                                                       
 100912 2024-07-06T12:05:12.9696724Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.300527Z","caller":"embed/etcd.go:599","msg":"serving peer traffic","address":"127.0.0.1:20001"}                                                                                                   
 100913 2024-07-06T12:05:12.9697558Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.300595Z","caller":"embed/etcd.go:571","msg":"cmux::serve","address":"127.0.0.1:20001"}                                                                                                            
 100914 2024-07-06T12:05:12.9699365Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.300598Z","caller":"embed/etcd.go:377","msg":"closing etcd                                                                                                                                         
        server","name":"e0","data-dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001","advertise-peer-urls":["https://localhost:20001"],"advertise-client-urls":["http://localhost:20000"]}                                                                                                           
 100915 2024-07-06T12:05:12.9700598Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.300657Z","caller":"etcdserver/server.go:1512","msg":"skipped leadership transfer; local server is not leader","local-member-id":"320a84688a8d3d46","current-leader-member-id":"0"}                
 100916 2024-07-06T12:05:12.9702562Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"warn","ts":"2024-07-06T12:00:36.300708Z","caller":"etcdserver/server.go:2139","msg":"failed to publish local member to cluster through raft","local-member-id":"320a84688a8d3d46","local-member-attributes":"{Name:e0             
        ClientURLs:[http://localhost:20000]}","request-path":"/0/members/320a84688a8d3d46/attributes","publish-timeout":"7s","error":"etcdserver: request cancelled"}                                                                                                                                                        
 100917 2024-07-06T12:05:12.9704489Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"warn","ts":"2024-07-06T12:00:36.300739Z","caller":"etcdserver/server.go:2139","msg":"failed to publish local member to cluster through raft","local-member-id":"320a84688a8d3d46","local-member-attributes":"{Name:e0             
        ClientURLs:[http://localhost:20000]}","request-path":"/0/members/320a84688a8d3d46/attributes","publish-timeout":"7s","error":"etcdserver: request cancelled"}                                                                                                                                                        
 100918 2024-07-06T12:05:12.9706087Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"warn","ts":"2024-07-06T12:00:36.300762Z","caller":"etcdserver/server.go:2129","msg":"stopped publish because server is stopped","local-member-id":"320a84688a8d3d46","local-member-attributes":"{Name:e0                          
        ClientURLs:[http://localhost:20000]}","publish-timeout":"7s","error":"etcdserver: server stopped"}                                                                                                                                                                                                                   
 100919 2024-07-06T12:05:12.9706930Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.301476Z","caller":"embed/etcd.go:581","msg":"stopping serving peer traffic","address":"127.0.0.1:20001"}                                                                                          
 100920 2024-07-06T12:05:12.9707755Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.301567Z","caller":"embed/etcd.go:586","msg":"stopped serving peer traffic","address":"127.0.0.1:20001"}                                                                                           
 100921 2024-07-06T12:05:12.9709348Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.301597Z","caller":"embed/etcd.go:379","msg":"closed etcd                                                                                                                                          
        server","name":"e0","data-dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001","advertise-peer-urls":["https://localhost:20001"],"advertise-client-urls":["http://localhost:20000"]}                                                                                                           
 100922 2024-07-06T12:05:12.9710519Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.301651Z","caller":"verify/verify.go:57","msg":"verification of persisted state","data-dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001"}                                 
 100923 2024-07-06T12:05:12.9711493Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.302359Z","caller":"verify/verify.go:129","msg":"verification: consistentIndex OK","backend-consistent-index":1,"hardstate-commit":1}                                                              
 100924 2024-07-06T12:05:12.9712799Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"info","ts":"2024-07-06T12:00:36.302648Z","caller":"verify/verify.go:68","msg":"verification of persisted state successful","data-dir":"/tmp/TestEtcdListenMetricsURLsWithMissingClientTLSInfo814463894/001"}                      
 100925 2024-07-06T12:05:12.9714142Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"warn","ts":"2024-07-06T12:00:36.302701Z","caller":"etcdmain/etcd.go:146","msg":"failed to start etcd","error":"client TLS key/cert (--cert-file, --key-file) must be provided for metrics secure url"}                            
 100926 2024-07-06T12:05:12.9716819Z /home/runner/work/etcd/etcd/bin/etcd-41945: {"level":"fatal","ts":"2024-07-06T12:00:36.302767Z","caller":"etcdmain/etcd.go:204","msg":"discovery failed","error":"client TLS key/cert (--cert-file, --key-file) must be provided for metrics secure                                     
        url","stacktrace":"go.etcd.io/etcd/server/v3/etcdmain.startEtcdOrProxyV2\n\tgo.etcd.io/etcd/server/v3/etcdmain/etcd.go:204\ngo.etcd.io/etcd/server/v3/etcdmain.Main\n\tgo.etcd.io/etcd/server/v3/etcdmain/main.go:40\nmain.main\n\tgo.etcd.io/etcd/server/v3/main.go:31\nruntime.main\n\truntime/proc.go:267"}       
 100927 2024-07-06T12:05:12.9717150Z --- FAIL: TestEtcdListenMetricsURLsWithMissingClientTLSInfo (0.93s)                                                                                                                                                                                                                     
 100928 2024-07-06T12:05:12.9717345Z     etcd_config_test.go:172: exit status 1

[ivanvc]

@jmhbnz, looks like (*ExpectProcess) Stop() is different in the main branch and in 3.5

3.5:

etcd/pkg/expect/expect.go

Lines 144 to 145 in b8d5e79

	// Stop kills the expect process and waits for it to exit.
	func (ep *ExpectProcess) Stop() error { return ep.close(true) }

main:

etcd/pkg/expect/expect.go

Lines 307 to 314 in 3c56849

	// Stop signals the process to terminate via SIGTERM
	func (ep *ExpectProcess) Stop() error {
	err := ep.Signal(syscall.SIGTERM)
	if err != nil && errors.Is(err, os.ErrProcessDone) {
	return nil
	}
	return err
	}

So, it seems like an error if the process finishes with 1 is expected in:

etcd/tests/e2e/etcd_config_test.go

Lines 171 to 173 in 154dba1

	if err := proc.Stop(); err != nil {
	t.Error(err)
	}

Changing the implementation on 3.5 to main's. Seems to work. But I don't know the impact on other tests that rely on Stop()'s current behavior

[jmhbnz]

@jmhbnz, looks like (*ExpectProcess) Stop() is different in the main branch and in 3.5

Nice find thank you - Yeah it's quite a significant change to also backport 5b163aa. For the purpose of this pr we might be better to just tweak the test case.

[ivanvc]

I confirmed that deleting the clean exit expectation solves the issue. It's also expected to exit with an error as it needs the certificates to start.

[ivanvc]

/lgtm

Thanks, @jmhbnz 🎉

[fuweid]

/lgtm
/approve

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: ahrtr, fuweid, ivanvc, jmhbnz

The full list of commands accepted by this bot can be found here.

Needs approval from an approver in each of these files:

• OWNERS

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment