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

[BUG] yurt-tunnel v0.5.0: x509 certificate is invalid #535

Closed
SataQiu opened this issue Oct 28, 2021 · 3 comments
Closed

[BUG] yurt-tunnel v0.5.0: x509 certificate is invalid #535

SataQiu opened this issue Oct 28, 2021 · 3 comments
Labels
kind/bug kind/bug

Comments

@SataQiu
Copy link
Member

SataQiu commented Oct 28, 2021

What happened:
The command executed:

[~]# kubectl logs -f -n kube-system yurt-tunnel-agent-5ng4l
Error from server: Get "https://192.168.0.247:10250/containerLogs/kube-system/yurt-tunnel-agent-5ng4l/yurt-tunnel-agent?follow=true": x509: certificate is valid for 139.224.119.237, 10.96.220.74, 127.0.0.1, 172.16.200.181, 172.16.200.183, 172.16.200.184, 10.96.80.107, not 192.168.0.247

The tunnel server logs:

I1028 10:01:34.753420       1 start.go:54] yurttunnel-server version: projectinfo.Info{GitVersion:"v0.5.0", GitCommit:"71d1da7", BuildDate:"2021-09-29T02:50:58Z", GoVersion:"go1.15.15", Compiler:"gc", Platform:"linux/amd64"}
W1028 10:01:34.753620       1 client_config.go:552] Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.
I1028 10:01:34.754241       1 options.go:155] yurttunnel server config: &config.Config{EgressSelectorEnabled:false, EnableIptables:true, EnableDNSController:true, IptablesSyncPeriod:60, DNSSyncPeriod:1800, CertDNSNames:[]string{}, CertIPs:[]net.IP{}, ListenAddrForAgent:"172.16.200.184:10262", ListenAddrForMaster:"172.16.200.184:10263", ListenInsecureAddrForMaster:"127.0.0.1:10264", ListenMetaAddr:"127.0.0.1:10265", RootCert:(*x509.CertPool)(0xc0000b6450), Client:(*kubernetes.Clientset)(0xc000396840), SharedInformerFactory:(*informers.sharedInformerFactory)(0xc00003b3b0), ServerCount:3, ProxyStrategy:"destHost", InterceptorServerUDSFile:""}
I1028 10:01:34.754462       1 leaderelection.go:242] attempting to acquire leader lease  kube-system/tunnel-dns-controller...
E1028 10:01:34.757338       1 iptables.go:200] failed to delete rule that nat chain OUTPUT jumps to TUNNEL-PORT: error checking rule: exit status 2: iptables v1.6.0: Couldn't load target `TUNNEL-PORT':No such file or directory

Try `iptables -h' or 'iptables --help' for more information.
I1028 10:01:39.765179       1 certmanager.go:82] subject of tunnel server certificate, ips=[]net.IP{net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x8b, 0xe0, 0x77, 0xed}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xa, 0x60, 0xdc, 0x4a}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x7f, 0x0, 0x0, 0x1}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xac, 0x10, 0xc8, 0xb5}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xac, 0x10, 0xc8, 0xb7}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xac, 0x10, 0xc8, 0xb8}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xa, 0x60, 0x50, 0x6b}}, dnsNames=[]string{"x-tunnel-server-svc", "x-tunnel-server-svc.kube-system", "x-tunnel-server-svc.kube-system.svc", "x-tunnel-server-svc.kube-system.svc.cluster.local", "x-tunnel-server-internal-svc", "x-tunnel-server-internal-svc.kube-system", "x-tunnel-server-internal-svc.kube-system.svc", "x-tunnel-server-internal-svc.kube-system.svc.cluster.local"}
I1028 10:01:39.765302       1 certificate_store.go:130] Loading cert/key pair from "/var/lib/yurttunnel-server/pki/yurttunnel-server-current.pem".
I1028 10:01:39.773465       1 csrapprover.go:55] starting the crsapprover
I1028 10:01:39.775413       1 handler.go:140] enqueue service add event for kube-system/x-tunnel-server-internal-svc
I1028 10:01:39.776042       1 handler.go:173] handle configmap add event for kube-system/yurt-tunnel-server-cfg to update localhost ports
I1028 10:01:39.776062       1 handler.go:92] enqueue configmap add event for kube-system/yurt-tunnel-server-cfg
I1028 10:01:39.778317       1 handler.go:42] enqueue node add event for izuf656ht24djbjyncwexwz
I1028 10:01:39.778332       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq6z
I1028 10:01:39.778342       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq7z
I1028 10:01:39.778347       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq8z
I1028 10:01:39.778354       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq5z
I1028 10:01:39.778697       1 csrapprover.go:125] non-approved and non-denied csr, enqueue: csr-hrkm9
I1028 10:01:39.873755       1 csrapprover.go:171] csr(csr-hrkm9) is approved
I1028 10:01:39.908294       1 iptables.go:456] clear conntrack entries for ports ["10250" "10255"] and nodes ["172.16.200.184" "172.16.200.183" "172.16.200.181" "172.16.200.182"]
E1028 10:01:39.913327       1 iptables.go:473] clear conntrack for 172.16.200.184:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
E1028 10:01:39.917006       1 iptables.go:473] clear conntrack for 172.16.200.183:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
E1028 10:01:39.920466       1 iptables.go:473] clear conntrack for 172.16.200.181:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
E1028 10:01:39.923869       1 iptables.go:473] clear conntrack for 172.16.200.182:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
I1028 10:01:39.927280       1 iptables.go:477] clear conntrack for 172.16.200.184:10255 successfully: "conntrack v1.4.4 (conntrack-tools): 1 flow entries have been deleted.\ntcp      6 86388 ESTABLISHED src=100.64.0.1 dst=172.16.200.184 sport=45164 dport=10255 src=172.16.200.184 dst=100.64.0.1 sport=10255 dport=45164 [ASSURED] mark=0 use=1\n"
I1028 10:01:39.930665       1 iptables.go:477] clear conntrack for 172.16.200.183:10255 successfully: "conntrack v1.4.4 (conntrack-tools): 1 flow entries have been deleted.\ntcp      6 86388 ESTABLISHED src=100.64.0.1 dst=172.16.200.183 sport=58178 dport=10255 src=172.16.200.183 dst=172.16.200.184 sport=10255 dport=58178 [ASSURED] mark=0 use=1\n"
I1028 10:01:39.934058       1 iptables.go:477] clear conntrack for 172.16.200.181:10255 successfully: "conntrack v1.4.4 (conntrack-tools): 1 flow entries have been deleted.\ntcp      6 86388 ESTABLISHED src=100.64.0.1 dst=172.16.200.181 sport=32836 dport=10255 src=172.16.200.181 dst=172.16.200.184 sport=10255 dport=32836 [ASSURED] mark=0 use=1\n"
I1028 10:01:39.937425       1 iptables.go:477] clear conntrack for 172.16.200.182:10255 successfully: "conntrack v1.4.4 (conntrack-tools): 1 flow entries have been deleted.\ntcp      6 86388 ESTABLISHED src=100.64.0.1 dst=172.16.200.182 sport=36298 dport=10255 src=172.16.200.182 dst=172.16.200.184 sport=10255 dport=36298 [ASSURED] mark=0 use=1\n"
I1028 10:01:39.937436       1 iptables.go:525] directly access nodes changed, [172.16.200.184 172.16.200.183 172.16.200.181 172.16.200.182] for ports [10250 10255]
I1028 10:01:44.773029       1 anpserver.go:106] start handling request from interceptor
I1028 10:01:44.773053       1 wraphandler.go:67] add localHostProxyMiddleware into wrap handler
I1028 10:01:44.773058       1 tracereq.go:63] 1 informer synced in traceReqMiddleware
I1028 10:01:44.773063       1 wraphandler.go:67] add TraceReqMiddleware into wrap handler
I1028 10:01:44.773111       1 anpserver.go:142] start handling https request from master at 172.16.200.184:10263
I1028 10:01:44.773122       1 anpserver.go:156] start handling http request from master at 127.0.0.1:10264
I1028 10:01:44.773190       1 anpserver.go:194] start handling connection from agents
I1028 10:01:44.773326       1 util.go:71] "start handling meta requests(metrics/pprof)" server endpoint="127.0.0.1:10265"
I1028 10:02:11.855222       1 csrapprover.go:125] non-approved and non-denied csr, enqueue: csr-crk7d
E1028 10:02:11.867288       1 csrapprover.go:190] failed to approve yurttunnel csr(csr-crk7d), Operation cannot be fulfilled on certificatesigningrequests.certificates.k8s.io "csr-crk7d": the object has been modified; please apply your changes to the latest version and try again
E1028 10:02:11.867309       1 csrapprover.go:97] Operation cannot be fulfilled on certificatesigningrequests.certificates.k8s.io "csr-crk7d": the object has been modified; please apply your changes to the latest version and try again
I1028 10:02:15.677400       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:15.677457       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc000314180)} agentID="192.168.0.247"
I1028 10:02:15.677471       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc000314180)} agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:21.071170       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:21.071217       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea000)} agentID="192.168.0.247"
I1028 10:02:21.071238       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea000)} agentID="izuf656ht24djbjyncwexwz"
E1028 10:02:21.074013       1 server.go:649] "stream read failure" err="rpc error: code = Canceled desc = context canceled"
I1028 10:02:21.074032       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea000)} identifier="192.168.0.247"
I1028 10:02:21.074042       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea000)} identifier="izuf656ht24djbjyncwexwz"
I1028 10:02:21.074079       1 server.go:668] "Close frontends connected to agent" count=0 agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:21.277918       1 leaderelection.go:252] successfully acquired lease kube-system/tunnel-dns-controller
I1028 10:02:21.278009       1 dns.go:195] starting tunnel dns controller
I1028 10:02:21.278019       1 shared_informer.go:223] Waiting for caches to sync for tunnel-dns-controller
I1028 10:02:21.278024       1 shared_informer.go:230] Caches are synced for tunnel-dns-controller 
I1028 10:02:21.279240       1 dns.go:315] sync tunnel server service as whole
I1028 10:02:21.279254       1 dns.go:324] sync dns record as whole
I1028 10:02:21.279258       1 dns.go:324] sync dns record as whole
I1028 10:02:21.287880       1 dns.go:315] sync tunnel server service as whole
I1028 10:02:21.480388       1 handler.go:165] adding node dns record for izuf656ht24djbjyncwexwz
I1028 10:02:21.680578       1 handler.go:165] adding node dns record for izuf6391ojb6oz4jyjjcq6z
I1028 10:02:21.880052       1 handler.go:165] adding node dns record for izuf6391ojb6oz4jyjjcq7z
I1028 10:02:22.079826       1 handler.go:165] adding node dns record for izuf6391ojb6oz4jyjjcq8z
I1028 10:02:22.279921       1 handler.go:165] adding node dns record for izuf6391ojb6oz4jyjjcq5z
I1028 10:02:26.233281       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:26.233314       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a300)} agentID="192.168.0.247"
I1028 10:02:26.233326       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a300)} agentID="izuf656ht24djbjyncwexwz"
E1028 10:02:26.236604       1 server.go:649] "stream read failure" err="rpc error: code = Canceled desc = context canceled"
I1028 10:02:26.236621       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a300)} identifier="192.168.0.247"
I1028 10:02:26.236628       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a300)} identifier="izuf656ht24djbjyncwexwz"
I1028 10:02:26.236644       1 server.go:668] "Close frontends connected to agent" count=0 agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:31.314798       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:31.314843       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a3c0)} agentID="192.168.0.247"
I1028 10:02:31.314852       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a3c0)} agentID="izuf656ht24djbjyncwexwz"
E1028 10:02:31.317644       1 server.go:649] "stream read failure" err="rpc error: code = Canceled desc = context canceled"
I1028 10:02:31.317666       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a3c0)} identifier="192.168.0.247"
I1028 10:02:31.317674       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a3c0)} identifier="izuf656ht24djbjyncwexwz"
I1028 10:02:31.317694       1 server.go:668] "Close frontends connected to agent" count=0 agentID="izuf656ht24djbjyncwexwz"
E1028 10:03:04.888596       1 server.go:649] "stream read failure" err="rpc error: code = Canceled desc = context canceled"
I1028 10:03:04.888631       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc000314180)} identifier="192.168.0.247"
I1028 10:03:04.888639       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc000314180)} identifier="izuf656ht24djbjyncwexwz"
I1028 10:03:04.888663       1 server.go:668] "Close frontends connected to agent" count=0 agentID="izuf656ht24djbjyncwexwz"
I1028 10:03:15.357214       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:03:15.357253       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a180)} agentID="192.168.0.247"
I1028 10:03:15.357261       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a180)} agentID="izuf656ht24djbjyncwexwz"
I1028 10:03:20.841300       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:03:20.841332       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea0c0)} agentID="192.168.0.247"
I1028 10:03:20.841339       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea0c0)} agentID="izuf656ht24djbjyncwexwz"
E1028 10:03:20.844375       1 server.go:649] "stream read failure" err="rpc error: code = Canceled desc = context canceled"
I1028 10:03:20.844392       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea0c0)} identifier="192.168.0.247"
I1028 10:03:20.844398       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea0c0)} identifier="izuf656ht24djbjyncwexwz"
I1028 10:03:20.844414       1 server.go:668] "Close frontends connected to agent" count=0 agentID="izuf656ht24djbjyncwexwz"
2021/10/28 10:03:25 http: TLS handshake error from 172.16.200.184:56662: remote error: tls: bad certificate
2021/10/28 10:03:34 http: TLS handshake error from 172.16.200.184:56774: remote error: tls: bad certificate
2021/10/28 10:09:43 http: TLS handshake error from 172.16.200.184:60496: remote error: tls: bad certificate
2021/10/28 10:13:32 http: TLS handshake error from 172.16.200.184:34544: remote error: tls: bad certificate
^C
[root@iZuf6391ojb6oz4jyjjcq6Z ~]# kubectl logs -f -n kube-system                     yurt-tunnel-agent-5ng4l
Error from server: Get "https://192.168.0.247:10250/containerLogs/kube-system/yurt-tunnel-agent-5ng4l/yurt-tunnel-agent?follow=true": x509: certificate is valid for 139.224.119.237, 10.96.220.74, 127.0.0.1, 172.16.200.181, 172.16.200.183, 172.16.200.184, 10.96.80.107, not 192.168.0.247
[root@iZuf6391ojb6oz4jyjjcq6Z ~]# kubectl logs -f -n kube-system                     yurt-tunnel-server-izuf6391ojb6oz4jyjjcq6z-d8ptq
I1028 10:01:34.753420       1 start.go:54] yurttunnel-server version: projectinfo.Info{GitVersion:"v0.5.0", GitCommit:"71d1da7", BuildDate:"2021-09-29T02:50:58Z", GoVersion:"go1.15.15", Compiler:"gc", Platform:"linux/amd64"}
W1028 10:01:34.753620       1 client_config.go:552] Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.
I1028 10:01:34.754241       1 options.go:155] yurttunnel server config: &config.Config{EgressSelectorEnabled:false, EnableIptables:true, EnableDNSController:true, IptablesSyncPeriod:60, DNSSyncPeriod:1800, CertDNSNames:[]string{}, CertIPs:[]net.IP{}, ListenAddrForAgent:"172.16.200.184:10262", ListenAddrForMaster:"172.16.200.184:10263", ListenInsecureAddrForMaster:"127.0.0.1:10264", ListenMetaAddr:"127.0.0.1:10265", RootCert:(*x509.CertPool)(0xc0000b6450), Client:(*kubernetes.Clientset)(0xc000396840), SharedInformerFactory:(*informers.sharedInformerFactory)(0xc00003b3b0), ServerCount:3, ProxyStrategy:"destHost", InterceptorServerUDSFile:""}
I1028 10:01:34.754462       1 leaderelection.go:242] attempting to acquire leader lease  kube-system/tunnel-dns-controller...
E1028 10:01:34.757338       1 iptables.go:200] failed to delete rule that nat chain OUTPUT jumps to TUNNEL-PORT: error checking rule: exit status 2: iptables v1.6.0: Couldn't load target `TUNNEL-PORT':No such file or directory

Try `iptables -h' or 'iptables --help' for more information.
I1028 10:01:39.765179       1 certmanager.go:82] subject of tunnel server certificate, ips=[]net.IP{net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x8b, 0xe0, 0x77, 0xed}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xa, 0x60, 0xdc, 0x4a}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x7f, 0x0, 0x0, 0x1}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xac, 0x10, 0xc8, 0xb5}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xac, 0x10, 0xc8, 0xb7}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xac, 0x10, 0xc8, 0xb8}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xa, 0x60, 0x50, 0x6b}}, dnsNames=[]string{"x-tunnel-server-svc", "x-tunnel-server-svc.kube-system", "x-tunnel-server-svc.kube-system.svc", "x-tunnel-server-svc.kube-system.svc.cluster.local", "x-tunnel-server-internal-svc", "x-tunnel-server-internal-svc.kube-system", "x-tunnel-server-internal-svc.kube-system.svc", "x-tunnel-server-internal-svc.kube-system.svc.cluster.local"}
I1028 10:01:39.765302       1 certificate_store.go:130] Loading cert/key pair from "/var/lib/yurttunnel-server/pki/yurttunnel-server-current.pem".
I1028 10:01:39.773465       1 csrapprover.go:55] starting the crsapprover
I1028 10:01:39.775413       1 handler.go:140] enqueue service add event for kube-system/x-tunnel-server-internal-svc
I1028 10:01:39.776042       1 handler.go:173] handle configmap add event for kube-system/yurt-tunnel-server-cfg to update localhost ports
I1028 10:01:39.776062       1 handler.go:92] enqueue configmap add event for kube-system/yurt-tunnel-server-cfg
I1028 10:01:39.778317       1 handler.go:42] enqueue node add event for izuf656ht24djbjyncwexwz
I1028 10:01:39.778332       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq6z
I1028 10:01:39.778342       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq7z
I1028 10:01:39.778347       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq8z
I1028 10:01:39.778354       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq5z
I1028 10:01:39.778697       1 csrapprover.go:125] non-approved and non-denied csr, enqueue: csr-hrkm9
I1028 10:01:39.873755       1 csrapprover.go:171] csr(csr-hrkm9) is approved
I1028 10:01:39.908294       1 iptables.go:456] clear conntrack entries for ports ["10250" "10255"] and nodes ["172.16.200.184" "172.16.200.183" "172.16.200.181" "172.16.200.182"]
E1028 10:01:39.913327       1 iptables.go:473] clear conntrack for 172.16.200.184:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
E1028 10:01:39.917006       1 iptables.go:473] clear conntrack for 172.16.200.183:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
E1028 10:01:39.920466       1 iptables.go:473] clear conntrack for 172.16.200.181:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
E1028 10:01:39.923869       1 iptables.go:473] clear conntrack for 172.16.200.182:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
I1028 10:01:39.927280       1 iptables.go:477] clear conntrack for 172.16.200.184:10255 successfully: "conntrack v1.4.4 (conntrack-tools): 1 flow entries have been deleted.\ntcp      6 86388 ESTABLISHED src=100.64.0.1 dst=172.16.200.184 sport=45164 dport=10255 src=172.16.200.184 dst=100.64.0.1 sport=10255 dport=45164 [ASSURED] mark=0 use=1\n"
I1028 10:01:39.930665       1 iptables.go:477] clear conntrack for 172.16.200.183:10255 successfully: "conntrack v1.4.4 (conntrack-tools): 1 flow entries have been deleted.\ntcp      6 86388 ESTABLISHED src=100.64.0.1 dst=172.16.200.183 sport=58178 dport=10255 src=172.16.200.183 dst=172.16.200.184 sport=10255 dport=58178 [ASSURED] mark=0 use=1\n"
I1028 10:01:39.934058       1 iptables.go:477] clear conntrack for 172.16.200.181:10255 successfully: "conntrack v1.4.4 (conntrack-tools): 1 flow entries have been deleted.\ntcp      6 86388 ESTABLISHED src=100.64.0.1 dst=172.16.200.181 sport=32836 dport=10255 src=172.16.200.181 dst=172.16.200.184 sport=10255 dport=32836 [ASSURED] mark=0 use=1\n"
I1028 10:01:39.937425       1 iptables.go:477] clear conntrack for 172.16.200.182:10255 successfully: "conntrack v1.4.4 (conntrack-tools): 1 flow entries have been deleted.\ntcp      6 86388 ESTABLISHED src=100.64.0.1 dst=172.16.200.182 sport=36298 dport=10255 src=172.16.200.182 dst=172.16.200.184 sport=10255 dport=36298 [ASSURED] mark=0 use=1\n"
I1028 10:01:39.937436       1 iptables.go:525] directly access nodes changed, [172.16.200.184 172.16.200.183 172.16.200.181 172.16.200.182] for ports [10250 10255]
I1028 10:01:44.773029       1 anpserver.go:106] start handling request from interceptor
I1028 10:01:44.773053       1 wraphandler.go:67] add localHostProxyMiddleware into wrap handler
I1028 10:01:44.773058       1 tracereq.go:63] 1 informer synced in traceReqMiddleware
I1028 10:01:44.773063       1 wraphandler.go:67] add TraceReqMiddleware into wrap handler
I1028 10:01:44.773111       1 anpserver.go:142] start handling https request from master at 172.16.200.184:10263
I1028 10:01:44.773122       1 anpserver.go:156] start handling http request from master at 127.0.0.1:10264
I1028 10:01:44.773190       1 anpserver.go:194] start handling connection from agents
I1028 10:01:44.773326       1 util.go:71] "start handling meta requests(metrics/pprof)" server endpoint="127.0.0.1:10265"
I1028 10:02:11.855222       1 csrapprover.go:125] non-approved and non-denied csr, enqueue: csr-crk7d
E1028 10:02:11.867288       1 csrapprover.go:190] failed to approve yurttunnel csr(csr-crk7d), Operation cannot be fulfilled on certificatesigningrequests.certificates.k8s.io "csr-crk7d": the object has been modified; please apply your changes to the latest version and try again
E1028 10:02:11.867309       1 csrapprover.go:97] Operation cannot be fulfilled on certificatesigningrequests.certificates.k8s.io "csr-crk7d": the object has been modified; please apply your changes to the latest version and try again
I1028 10:02:15.677400       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:15.677457       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc000314180)} agentID="192.168.0.247"
I1028 10:02:15.677471       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc000314180)} agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:21.071170       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:21.071217       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea000)} agentID="192.168.0.247"
I1028 10:02:21.071238       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea000)} agentID="izuf656ht24djbjyncwexwz"
E1028 10:02:21.074013       1 server.go:649] "stream read failure" err="rpc error: code = Canceled desc = context canceled"
I1028 10:02:21.074032       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea000)} identifier="192.168.0.247"
I1028 10:02:21.074042       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea000)} identifier="izuf656ht24djbjyncwexwz"
I1028 10:02:21.074079       1 server.go:668] "Close frontends connected to agent" count=0 agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:21.277918       1 leaderelection.go:252] successfully acquired lease kube-system/tunnel-dns-controller
I1028 10:02:21.278009       1 dns.go:195] starting tunnel dns controller
I1028 10:02:21.278019       1 shared_informer.go:223] Waiting for caches to sync for tunnel-dns-controller
I1028 10:02:21.278024       1 shared_informer.go:230] Caches are synced for tunnel-dns-controller 
I1028 10:02:21.279240       1 dns.go:315] sync tunnel server service as whole
I1028 10:02:21.279254       1 dns.go:324] sync dns record as whole
I1028 10:02:21.279258       1 dns.go:324] sync dns record as whole
I1028 10:02:21.287880       1 dns.go:315] sync tunnel server service as whole
I1028 10:02:21.480388       1 handler.go:165] adding node dns record for izuf656ht24djbjyncwexwz
I1028 10:02:21.680578       1 handler.go:165] adding node dns record for izuf6391ojb6oz4jyjjcq6z
I1028 10:02:21.880052       1 handler.go:165] adding node dns record for izuf6391ojb6oz4jyjjcq7z
I1028 10:02:22.079826       1 handler.go:165] adding node dns record for izuf6391ojb6oz4jyjjcq8z
I1028 10:02:22.279921       1 handler.go:165] adding node dns record for izuf6391ojb6oz4jyjjcq5z
I1028 10:02:26.233281       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:26.233314       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a300)} agentID="192.168.0.247"
I1028 10:02:26.233326       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a300)} agentID="izuf656ht24djbjyncwexwz"
E1028 10:02:26.236604       1 server.go:649] "stream read failure" err="rpc error: code = Canceled desc = context canceled"
I1028 10:02:26.236621       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a300)} identifier="192.168.0.247"
I1028 10:02:26.236628       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a300)} identifier="izuf656ht24djbjyncwexwz"
I1028 10:02:26.236644       1 server.go:668] "Close frontends connected to agent" count=0 agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:31.314798       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:02:31.314843       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a3c0)} agentID="192.168.0.247"
I1028 10:02:31.314852       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a3c0)} agentID="izuf656ht24djbjyncwexwz"
E1028 10:02:31.317644       1 server.go:649] "stream read failure" err="rpc error: code = Canceled desc = context canceled"
I1028 10:02:31.317666       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a3c0)} identifier="192.168.0.247"
I1028 10:02:31.317674       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a3c0)} identifier="izuf656ht24djbjyncwexwz"
I1028 10:02:31.317694       1 server.go:668] "Close frontends connected to agent" count=0 agentID="izuf656ht24djbjyncwexwz"
E1028 10:03:04.888596       1 server.go:649] "stream read failure" err="rpc error: code = Canceled desc = context canceled"
I1028 10:03:04.888631       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc000314180)} identifier="192.168.0.247"
I1028 10:03:04.888639       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc000314180)} identifier="izuf656ht24djbjyncwexwz"
I1028 10:03:04.888663       1 server.go:668] "Close frontends connected to agent" count=0 agentID="izuf656ht24djbjyncwexwz"
I1028 10:03:15.357214       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:03:15.357253       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a180)} agentID="192.168.0.247"
I1028 10:03:15.357261       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00062a180)} agentID="izuf656ht24djbjyncwexwz"
I1028 10:03:20.841300       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1028 10:03:20.841332       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea0c0)} agentID="192.168.0.247"
I1028 10:03:20.841339       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea0c0)} agentID="izuf656ht24djbjyncwexwz"
E1028 10:03:20.844375       1 server.go:649] "stream read failure" err="rpc error: code = Canceled desc = context canceled"
I1028 10:03:20.844392       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea0c0)} identifier="192.168.0.247"
I1028 10:03:20.844398       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0004ea0c0)} identifier="izuf656ht24djbjyncwexwz"
I1028 10:03:20.844414       1 server.go:668] "Close frontends connected to agent" count=0 agentID="izuf656ht24djbjyncwexwz"
2021/10/28 10:03:25 http: TLS handshake error from 172.16.200.184:56662: remote error: tls: bad certificate
2021/10/28 10:03:34 http: TLS handshake error from 172.16.200.184:56774: remote error: tls: bad certificate
2021/10/28 10:09:43 http: TLS handshake error from 172.16.200.184:60496: remote error: tls: bad certificate
2021/10/28 10:13:32 http: TLS handshake error from 172.16.200.184:34544: remote error: tls: bad certificate
2021/10/28 10:17:41 http: TLS handshake error from 172.16.200.184:37052: remote error: tls: bad certificate

The tunnel agent logs:

I1028 10:03:10.313738       1 start.go:51] yurttunnel-agent version: projectinfo.Info{GitVersion:"v0.5.0", GitCommit:"71d1da7", BuildDate:"2021-09-29T02:50:58Z", GoVersion:"go1.15.15", Compiler:"gc", Platform:"linux/amd64"}
I1028 10:03:10.314376       1 options.go:136] ipv4=192.168.0.247&host=izuf656ht24djbjyncwexwz is set for agent identifies
I1028 10:03:10.314382       1 options.go:141] neither --kube-config nor --apiserver-addr is set, will use /etc/kubernetes/kubelet.conf as the kubeconfig
I1028 10:03:10.314386       1 options.go:145] create the clientset based on the kubeconfig(/etc/kubernetes/kubelet.conf).
I1028 10:03:10.343983       1 start.go:87] yurttunnel-server address: 139.224.119.237:32502
I1028 10:03:10.344044       1 certificate_store.go:130] Loading cert/key pair from "/var/lib/yurttunnel-agent/pki/yurttunnel-agent-current.pem".
I1028 10:03:15.344462       1 start.go:106] certificate yurttunnel-agent ok
I1028 10:03:15.344735       1 anpagent.go:57] start serving grpc request redirected from yurttunnel-server: 139.224.119.237:32502
I1028 10:03:15.344948       1 util.go:71] "start handling meta requests(metrics/pprof)" server endpoint="127.0.0.1:10266"
I1028 10:03:15.359084       1 client.go:224] "Connect to" server="5b751dbd-0d9b-4b13-ab32-0f038ea16eb8"
I1028 10:03:15.359099       1 clientset.go:190] "sync added client connecting to proxy server" serverID="5b751dbd-0d9b-4b13-ab32-0f038ea16eb8"
I1028 10:03:15.359125       1 client.go:326] "Start serving" serverID="5b751dbd-0d9b-4b13-ab32-0f038ea16eb8"
I1028 10:03:20.842978       1 client.go:224] "Connect to" server="5b751dbd-0d9b-4b13-ab32-0f038ea16eb8"
E1028 10:03:20.843002       1 clientset.go:186] "closing connection failure when adding a client" err="client for proxy server 5b751dbd-0d9b-4b13-ab32-0f038ea16eb8 already exists"
I1028 10:03:26.189100       1 client.go:224] "Connect to" server="05c1e3c2-e97c-4695-b082-078308514afa"
I1028 10:03:26.189119       1 clientset.go:190] "sync added client connecting to proxy server" serverID="05c1e3c2-e97c-4695-b082-078308514afa"
I1028 10:03:26.189140       1 client.go:326] "Start serving" serverID="05c1e3c2-e97c-4695-b082-078308514afa"
I1028 10:03:31.422656       1 client.go:224] "Connect to" server="05c1e3c2-e97c-4695-b082-078308514afa"
E1028 10:03:31.422677       1 clientset.go:186] "closing connection failure when adding a client" err="client for proxy server 05c1e3c2-e97c-4695-b082-078308514afa already exists"
I1028 10:03:36.649221       1 client.go:224] "Connect to" server="05c1e3c2-e97c-4695-b082-078308514afa"
E1028 10:03:36.649240       1 clientset.go:186] "closing connection failure when adding a client" err="client for proxy server 05c1e3c2-e97c-4695-b082-078308514afa already exists"
I1028 10:03:42.006643       1 client.go:224] "Connect to" server="05c1e3c2-e97c-4695-b082-078308514afa"
E1028 10:03:42.006663       1 clientset.go:186] "closing connection failure when adding a client" err="client for proxy server 05c1e3c2-e97c-4695-b082-078308514afa already exists"
I1028 10:03:47.054318       1 client.go:224] "Connect to" server="2c985ce2-adc5-4613-a947-25a63e415075"
I1028 10:03:47.054337       1 clientset.go:190] "sync added client connecting to proxy server" serverID="2c985ce2-adc5-4613-a947-25a63e415075"
I1028 10:03:47.054356       1 client.go:326] "Start serving" serverID="2c985ce2-adc5-4613-a947-25a63e415075"

What you expected to happen:

kubectl logs can work well through yurt-tunnel.

How to reproduce it (as minimally and precisely as possible):

Anything else we need to know?:

Environment:

  • OpenYurt version: v0.5.0
  • Kubernetes version (use kubectl version): v1.20.4
  • OS (e.g: cat /etc/os-release):
  • Kernel (e.g. uname -a):
  • Install tools:
  • Others:

others

/kind bug
@SataQiu SataQiu added the kind/bug kind/bug label Oct 28, 2021
@SataQiu SataQiu changed the title [BUG] yurt-tunnel x509: certificate is valid [BUG] yurt-tunnel v0.5.0: x509: certificate is valid Oct 28, 2021
@SataQiu SataQiu changed the title [BUG] yurt-tunnel v0.5.0: x509: certificate is valid [BUG] yurt-tunnel v0.5.0: x509 certificate is invalid Oct 28, 2021
@rambohe-ch
Copy link
Member

@SataQiu Thank you for raising issue.

What happened: The command executed:

[~]# kubectl logs -f -n kube-system yurt-tunnel-agent-5ng4l
Error from server: Get "https://192.168.0.247:10250/containerLogs/kube-system/yurt-tunnel-agent-5ng4l/yurt-tunnel-agent?follow=true": x509: certificate is valid for 139.224.119.237, 10.96.220.74, 127.0.0.1, 172.16.200.181, 172.16.200.183, 172.16.200.184, 10.96.80.107, not 192.168.0.247

It looks like that yurt-tunnel-server has used an old certificate, you can delete /var/lib/yurt-tunnel-server directory on cloud node and restart yurt-tunnel-server pod for generating new certificate.

btw: #525 will fix the above case: when the address of yurt-tunnel-server changed, certificate will be updated automatically.

@SataQiu
Copy link
Member Author

SataQiu commented Oct 29, 2021

Unfortunately, clearing certificates does not solve this problem.
Tunnel Server logs with --v=5:

I1029 06:47:29.669859       1 start.go:53] yurttunnel-server version: projectinfo.Info{GitVersion:"v0.5.0", GitCommit:"eff2b5d", BuildDate:"2021-10-29T04:57:01Z", GoVersion:"go1.15.15", Compiler:"gc", Platform:"linux/amd64"}
W1029 06:47:29.670070       1 client_config.go:552] Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.
I1029 06:47:29.670715       1 options.go:155] yurttunnel server config: &config.Config{EgressSelectorEnabled:false, EnableIptables:true, EnableDNSController:true, IptablesSyncPeriod:60, DNSSyncPeriod:1800, CertDNSNames:[]string{}, CertIPs:[]net.IP{}, ListenAddrForAgent:"172.16.200.184:10262", ListenAddrForMaster:"172.16.200.184:10263", ListenInsecureAddrForMaster:"127.0.0.1:10264", ListenMetaAddr:"127.0.0.1:10265", RootCert:(*x509.CertPool)(0xc00049e480), Client:(*kubernetes.Clientset)(0xc0003746e0), SharedInformerFactory:(*informers.sharedInformerFactory)(0xc000119360), ServerCount:3, ProxyStrategy:"destHost", InterceptorServerUDSFile:""}
I1029 06:47:29.670919       1 leaderelection.go:242] attempting to acquire leader lease  kube-system/tunnel-dns-controller...
E1029 06:47:29.673740       1 iptables.go:200] failed to delete rule that nat chain OUTPUT jumps to TUNNEL-PORT: error checking rule: exit status 2: iptables v1.6.0: Couldn't load target `TUNNEL-PORT':No such file or directory

Try `iptables -h' or 'iptables --help' for more information.
I1029 06:47:34.685846       1 certmanager.go:82] subject of tunnel server certificate, ips=[]net.IP{net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x8b, 0xe0, 0x77, 0xed}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xa, 0x60, 0xdc, 0x4a}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x7f, 0x0, 0x0, 0x1}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xac, 0x10, 0xc8, 0xb5}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xac, 0x10, 0xc8, 0xb7}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xac, 0x10, 0xc8, 0xb8}, net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xa, 0x60, 0x50, 0x6b}}, dnsNames=[]string{"x-tunnel-server-svc", "x-tunnel-server-svc.kube-system", "x-tunnel-server-svc.kube-system.svc", "x-tunnel-server-svc.kube-system.svc.cluster.local", "x-tunnel-server-internal-svc", "x-tunnel-server-internal-svc.kube-system", "x-tunnel-server-internal-svc.kube-system.svc", "x-tunnel-server-internal-svc.kube-system.svc.cluster.local"}
I1029 06:47:34.685921       1 certificate_store.go:130] Loading cert/key pair from "/var/lib/yurttunnel-server/pki/yurttunnel-server-current.pem".
I1029 06:47:34.695546       1 trace.go:201] Trace[1427131847]: "Reflector ListAndWatch" name:pkg/mod/k8s.io/client-go@v0.18.8/tools/cache/reflector.go:125 (29-Oct-2021 06:47:00.693) (total time: 1ms):
Trace[1427131847]: ---"Objects listed" 1ms (06:47:00.695)
Trace[1427131847]: ---"Resource version extracted" 0ms (06:47:00.695)
Trace[1427131847]: ---"Objects extracted" 0ms (06:47:00.695)
Trace[1427131847]: ---"SyncWith done" 0ms (06:47:00.695)
Trace[1427131847]: ---"Resource version updated" 0ms (06:47:00.695)
Trace[1427131847]: [1.926917ms] [1.926917ms] END
I1029 06:47:34.695602       1 handler.go:173] handle configmap add event for kube-system/yurt-tunnel-server-cfg to update localhost ports
I1029 06:47:34.695622       1 handler.go:92] enqueue configmap add event for kube-system/yurt-tunnel-server-cfg
I1029 06:47:34.696435       1 trace.go:201] Trace[911902081]: "Reflector ListAndWatch" name:pkg/mod/k8s.io/client-go@v0.18.8/tools/cache/reflector.go:125 (29-Oct-2021 06:47:00.693) (total time: 2ms):
Trace[911902081]: ---"Objects listed" 2ms (06:47:00.696)
Trace[911902081]: ---"Resource version extracted" 0ms (06:47:00.696)
Trace[911902081]: ---"Objects extracted" 0ms (06:47:00.696)
Trace[911902081]: ---"SyncWith done" 0ms (06:47:00.696)
Trace[911902081]: ---"Resource version updated" 0ms (06:47:00.696)
Trace[911902081]: [2.804723ms] [2.804723ms] END
I1029 06:47:34.696487       1 handler.go:140] enqueue service add event for kube-system/x-tunnel-server-internal-svc
I1029 06:47:34.698183       1 trace.go:201] Trace[140954425]: "Reflector ListAndWatch" name:pkg/mod/k8s.io/client-go@v0.18.8/tools/cache/reflector.go:125 (29-Oct-2021 06:47:00.693) (total time: 4ms):
Trace[140954425]: ---"Objects listed" 4ms (06:47:00.698)
Trace[140954425]: ---"Resource version extracted" 0ms (06:47:00.698)
Trace[140954425]: ---"Objects extracted" 0ms (06:47:00.698)
Trace[140954425]: ---"SyncWith done" 0ms (06:47:00.698)
Trace[140954425]: ---"Resource version updated" 0ms (06:47:00.698)
Trace[140954425]: [4.57438ms] [4.57438ms] END
I1029 06:47:34.698261       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq6z
I1029 06:47:34.698286       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq7z
I1029 06:47:34.698291       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq8z
I1029 06:47:34.698296       1 handler.go:42] enqueue node add event for izuf6391ojb6oz4jyjjcq5z
I1029 06:47:34.698299       1 handler.go:42] enqueue node add event for izuf656ht24djbjyncwexwz
I1029 06:47:34.699381       1 trace.go:201] Trace[208240456]: "Reflector ListAndWatch" name:pkg/mod/k8s.io/client-go@v0.18.8/tools/cache/reflector.go:125 (29-Oct-2021 06:47:00.698) (total time: 1ms):
Trace[208240456]: ---"Objects listed" 1ms (06:47:00.699)
Trace[208240456]: ---"Resource version extracted" 0ms (06:47:00.699)
Trace[208240456]: ---"Objects extracted" 0ms (06:47:00.699)
Trace[208240456]: ---"SyncWith done" 0ms (06:47:00.699)
Trace[208240456]: ---"Resource version updated" 0ms (06:47:00.699)
Trace[208240456]: [1.163206ms] [1.163206ms] END
I1029 06:47:34.776667       1 iptables.go:239] nodes without yurttunnel-agent: 172.16.200.184,172.16.200.183,172.16.200.181,172.16.200.182
I1029 06:47:34.827974       1 iptables.go:456] clear conntrack entries for ports ["10250" "10255"] and nodes ["172.16.200.184" "172.16.200.183" "172.16.200.181" "172.16.200.182"]
E1029 06:47:34.832010       1 iptables.go:473] clear conntrack for 172.16.200.184:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
E1029 06:47:34.835796       1 iptables.go:473] clear conntrack for 172.16.200.183:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
E1029 06:47:34.839336       1 iptables.go:473] clear conntrack for 172.16.200.181:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
E1029 06:47:34.842832       1 iptables.go:473] clear conntrack for 172.16.200.182:10250 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
E1029 06:47:34.846299       1 iptables.go:473] clear conntrack for 172.16.200.184:10255 failed: "conntrack v1.4.4 (conntrack-tools): 0 flow entries have been deleted.\n", error message: exit status 1
I1029 06:47:34.849806       1 iptables.go:477] clear conntrack for 172.16.200.183:10255 successfully: "conntrack v1.4.4 (conntrack-tools): 1 flow entries have been deleted.\ntcp      6 86393 ESTABLISHED src=100.64.0.1 dst=172.16.200.183 sport=59702 dport=10255 src=172.16.200.183 dst=172.16.200.184 sport=10255 dport=59702 [ASSURED] mark=0 use=1\n"
I1029 06:47:34.853311       1 iptables.go:477] clear conntrack for 172.16.200.181:10255 successfully: "conntrack v1.4.4 (conntrack-tools): 1 flow entries have been deleted.\ntcp      6 86393 ESTABLISHED src=100.64.0.1 dst=172.16.200.181 sport=34360 dport=10255 src=172.16.200.181 dst=172.16.200.184 sport=10255 dport=34360 [ASSURED] mark=0 use=1\n"
I1029 06:47:34.856801       1 iptables.go:477] clear conntrack for 172.16.200.182:10255 successfully: "conntrack v1.4.4 (conntrack-tools): 1 flow entries have been deleted.\ntcp      6 86393 ESTABLISHED src=100.64.0.1 dst=172.16.200.182 sport=37822 dport=10255 src=172.16.200.182 dst=172.16.200.184 sport=10255 dport=37822 [ASSURED] mark=0 use=1\n"
I1029 06:47:34.856816       1 iptables.go:525] directly access nodes changed, [172.16.200.184 172.16.200.183 172.16.200.181 172.16.200.182] for ports [10250 10255]
I1029 06:47:39.693649       1 anpserver.go:106] start handling request from interceptor
I1029 06:47:39.693684       1 wraphandler.go:61] 2 middlewares will be added into wrap handler
I1029 06:47:39.693695       1 wraphandler.go:67] add localHostProxyMiddleware into wrap handler
I1029 06:47:39.693699       1 tracereq.go:63] 1 informer synced in traceReqMiddleware
I1029 06:47:39.693702       1 wraphandler.go:67] add TraceReqMiddleware into wrap handler
I1029 06:47:39.693761       1 anpserver.go:142] start handling https request from master at 172.16.200.184:10263
I1029 06:47:39.693778       1 anpserver.go:156] start handling http request from master at 127.0.0.1:10264
I1029 06:47:39.693833       1 anpserver.go:194] start handling connection from agents
I1029 06:47:39.693965       1 util.go:71] "start handling meta requests(metrics/pprof)" server endpoint="127.0.0.1:10265"
I1029 06:47:40.682137       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1029 06:47:40.682172       1 server.go:220] "Add the agent to DestHostBackendManager" agent address="192.168.0.247"
I1029 06:47:40.682186       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00037a000)} agentID="192.168.0.247"
I1029 06:47:40.682196       1 server.go:228] "Add the agent to DestHostBackendManager" agent address="izuf656ht24djbjyncwexwz"
I1029 06:47:40.682203       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00037a000)} agentID="izuf656ht24djbjyncwexwz"
I1029 06:48:34.859530       1 iptables.go:239] nodes without yurttunnel-agent: 172.16.200.181,172.16.200.182,172.16.200.184,172.16.200.183
E1029 06:48:43.471073       1 server.go:649] "stream read failure" err="rpc error: code = Canceled desc = context canceled"
I1029 06:48:43.471102       1 server.go:250] "Remove the agent from the DestHostBackendManager" agentHost="192.168.0.247"
I1029 06:48:43.471117       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00037a000)} identifier="192.168.0.247"
I1029 06:48:43.471125       1 server.go:258] "Remove the agent from the DestHostBackendManager" agentHost="izuf656ht24djbjyncwexwz"
I1029 06:48:43.471131       1 backend_manager.go:210] "Remove connection for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00037a000)} identifier="izuf656ht24djbjyncwexwz"
I1029 06:48:43.471172       1 server.go:753] "Close backend of agent" backend=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc00037a000)} agentID="izuf656ht24djbjyncwexwz"
I1029 06:48:43.471181       1 server.go:668] "Close frontends connected to agent" count=0 agentID="izuf656ht24djbjyncwexwz"
I1029 06:48:59.911487       1 server.go:616] "Connect request from agent" agentID="izuf656ht24djbjyncwexwz"
I1029 06:48:59.911513       1 server.go:220] "Add the agent to DestHostBackendManager" agent address="192.168.0.247"
I1029 06:48:59.911528       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0002ae0c0)} agentID="192.168.0.247"
I1029 06:48:59.911535       1 server.go:228] "Add the agent to DestHostBackendManager" agent address="izuf656ht24djbjyncwexwz"
I1029 06:48:59.911542       1 backend_manager.go:184] "Register backend for agent" connection=&agent.agentServiceConnectServer{ServerStream:(*grpc.serverStream)(0xc0002ae0c0)} agentID="izuf656ht24djbjyncwexwz"
2021/10/29 06:49:05 http: TLS handshake error from 172.16.200.184:34406: remote error: tls: bad certificate
I1029 06:49:34.859127       1 iptables.go:239] nodes without yurttunnel-agent: 172.16.200.184,172.16.200.183,172.16.200.181,172.16.200.182
I1029 06:50:34.858953       1 iptables.go:239] nodes without yurttunnel-agent: 172.16.200.181,172.16.200.182,172.16.200.184,172.16.200.183
I1029 06:51:34.858838       1 iptables.go:239] nodes without yurttunnel-agent: 172.16.200.184,172.16.200.183,172.16.200.181,172.16.200.182
I1029 06:52:34.858679       1 iptables.go:239] nodes without yurttunnel-agent: 172.16.200.184,172.16.200.183,172.16.200.181,172.16.200.182
2021/10/29 06:52:45 http: TLS handshake error from 172.16.200.184:37152: remote error: tls: bad certificate

Tunnel Agent logs with --v=5:

I1029 06:48:49.388440       1 start.go:51] yurttunnel-agent version: projectinfo.Info{GitVersion:"v0.5.0", GitCommit:"eff2b5d", BuildDate:"2021-10-29T04:57:01Z", GoVersion:"go1.15.15", Compiler:"gc", Platform:"linux/amd64"}
I1029 06:48:49.388890       1 options.go:136] ipv4=192.168.0.247&host=izuf656ht24djbjyncwexwz is set for agent identifies
I1029 06:48:49.388896       1 options.go:141] neither --kube-config nor --apiserver-addr is set, will use /etc/kubernetes/kubelet.conf as the kubeconfig
I1029 06:48:49.388902       1 options.go:145] create the clientset based on the kubeconfig(/etc/kubernetes/kubelet.conf).
I1029 06:48:49.417200       1 start.go:87] yurttunnel-server address: 139.224.119.237:32502
I1029 06:48:49.417271       1 certificate_store.go:130] Loading cert/key pair from "/var/lib/yurttunnel-agent/pki/yurttunnel-agent-current.pem".
I1029 06:48:54.417667       1 start.go:106] certificate yurttunnel-agent ok
I1029 06:48:54.417948       1 anpagent.go:57] start serving grpc request redirected from yurttunnel-server: 139.224.119.237:32502
I1029 06:48:54.418169       1 util.go:71] "start handling meta requests(metrics/pprof)" server endpoint="127.0.0.1:10266"
I1029 06:48:54.430367       1 client.go:224] "Connect to" server="a5abd005-3576-4a56-a8cf-302d923089e4"
I1029 06:48:54.430381       1 clientset.go:190] "sync added client connecting to proxy server" serverID="a5abd005-3576-4a56-a8cf-302d923089e4"
I1029 06:48:54.430427       1 client.go:326] "Start serving" serverID="a5abd005-3576-4a56-a8cf-302d923089e4"
I1029 06:48:59.913296       1 client.go:224] "Connect to" server="df3cc5b6-20bd-46c7-b608-4d26fed40ce2"
I1029 06:48:59.913314       1 clientset.go:190] "sync added client connecting to proxy server" serverID="df3cc5b6-20bd-46c7-b608-4d26fed40ce2"
I1029 06:48:59.913334       1 client.go:326] "Start serving" serverID="df3cc5b6-20bd-46c7-b608-4d26fed40ce2"
I1029 06:49:05.261006       1 client.go:224] "Connect to" server="946d57c4-8ab7-47d3-81c9-79f326ed214f"
I1029 06:49:05.261024       1 clientset.go:190] "sync added client connecting to proxy server" serverID="946d57c4-8ab7-47d3-81c9-79f326ed214f"
I1029 06:49:05.261052       1 client.go:326] "Start serving" serverID="946d57c4-8ab7-47d3-81c9-79f326ed214f"

@rambohe-ch
Copy link
Member

rambohe-ch commented Oct 29, 2021 •
edited
Loading

@SataQiu Thanks for your feedback.
please skip the former reply. and please reference the following reply.

  • reason:
    the reason of following error:
[~]# kubectl logs -f -n kube-system yurt-tunnel-agent-5ng4l
Error from server: Get "https://192.168.0.247:10250/containerLogs/kube-system/yurt-tunnel-agent-5ng4l/yurt-tunnel-agent?follow=true": x509: certificate is valid for 139.224.119.237, 10.96.220.74, 127.0.0.1, 172.16.200.181, 172.16.200.183, 172.16.200.184, 10.96.80.107, not 192.168.0.247

is: kube-apiserver have verified server certificate of yurt-tunnel-server when use nodeIP:10250 access kubelet through yurt-tunnel. and nodeIP is not included in server certificate extensions, so TLS handshake failed.

  • solution:
    kube-apiserver need to skip verify server certificate of yurt-tunnel-server, so kube-apiserver parameter kubelet-certificate-authority should not configured.

@rambohe-ch rambohe-ch mentioned this issue Aug 15, 2022
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
kind/bug kind/bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@SataQiu @rambohe-ch