Skip to content
This repository has been archived by the owner on Jul 30, 2021. It is now read-only.

TLS errors in apiserver when running with calico #960

Closed
weikinhuang opened this issue Apr 6, 2018 · 6 comments
Closed

TLS errors in apiserver when running with calico #960

weikinhuang opened this issue Apr 6, 2018 · 6 comments

Comments

@weikinhuang
Copy link
Contributor

weikinhuang commented Apr 6, 2018 •
edited
Loading

Since the update to v1.10.0 for k8s and calico 3.0.3 I have been having some networking issues especially around hostPort. (Using bootkube:master) with v1.10.0 for all k8s services.

Logs for the apiserver continuously print out:

W0406 01:20:52.324496       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes 7d777032-3936-11e8-8d31-000c2903e197 2724 0 2018-04-06 01:04:43 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
I0406 01:20:53.933315       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46390: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:20:55.934019       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46400: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:20:57.934591       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46406: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:20:59.935834       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46416: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:01.937007       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46428: tls: client offered an unsupported, maximum protocol version of 300
W0406 01:21:02.335075       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes 7d777032-3936-11e8-8d31-000c2903e197 2742 0 2018-04-06 01:04:43 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
I0406 01:21:03.937739       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46440: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:05.938761       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46450: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:07.940131       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46456: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:09.940862       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46466: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:11.942327       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46478: tls: client offered an unsupported, maximum protocol version of 300
W0406 01:21:12.345053       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes 7d777032-3936-11e8-8d31-000c2903e197 2761 0 2018-04-06 01:04:43 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
I0406 01:21:13.943879       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46490: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:15.944653       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46500: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:17.945835       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46506: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:19.947143       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46516: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:21.947902       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46528: tls: client offered an unsupported, maximum protocol version of 300
W0406 01:21:22.353828       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes 7d777032-3936-11e8-8d31-000c2903e197 2781 0 2018-04-06 01:04:43 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
I0406 01:21:23.949051       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46540: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:25.950218       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46550: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:27.950714       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46556: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:29.951480       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46566: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:31.952504       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46578: tls: client offered an unsupported, maximum protocol version of 300
W0406 01:21:32.364330       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes 7d777032-3936-11e8-8d31-000c2903e197 2800 0 2018-04-06 01:04:43 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
I0406 01:21:33.953725       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46590: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:35.955349       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46600: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:37.956636       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46606: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:39.958281       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46616: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:41.959989       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46628: tls: client offered an unsupported, maximum protocol version of 300
W0406 01:21:42.373542       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes 7d777032-3936-11e8-8d31-000c2903e197 2819 0 2018-04-06 01:04:43 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
I0406 01:21:43.961479       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46640: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:45.962635       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46650: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:47.963907       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46656: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:49.964578       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46666: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:51.965458       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46678: tls: client offered an unsupported, maximum protocol version of 300
W0406 01:21:52.382706       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes 7d777032-3936-11e8-8d31-000c2903e197 2838 0 2018-04-06 01:04:43 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
I0406 01:21:53.967322       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46690: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:55.968773       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46700: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:57.970349       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46706: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:21:59.972341       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46716: tls: client offered an unsupported, maximum protocol version of 300
I0406 01:22:01.972368       1 logs.go:49] http: TLS handshake error from 127.0.0.1:46728: tls: client offered an unsupported, maximum protocol version of 300
W0406 01:22:02.392073       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes 7d777032-3936-11e8-8d31-000c2903e197 2857 0 2018-04-06 01:04:43 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}

The timing of these logs seem to correlate with calico trying to initialize a watcher

2018-04-06 01:21:08.863 [INFO][81] watcher.go 124: Watch event indicates a terminated watcher resource="BGPPeer (custom)"
2018-04-06 01:21:08.863 [INFO][81] watcher.go 85: Kubernetes watcher/converter stopped, closing result channel resource="BGPPeer (custom)"
2018-04-06 01:21:08.863 [INFO][81] watchercache.go 127: Starting watch sync/resync processing ListRoot="/calico/resources/v3/projectcalico.org/bgppeers"
2018-04-06 01:21:08.863 [INFO][81] watchercache.go 129: Stopping previous watcher ListRoot="/calico/resources/v3/projectcalico.org/bgppeers"
2018-04-06 01:21:08.863 [INFO][81] watchersyncer.go 153: Error received in main syncer event processing loop error=watch terminated (closedByRemote:true): terminating error event from Kubernetes watcher: closed by remote
2018-04-06 01:21:08.864 [INFO][81] watcher.go 83: Kubernetes watcher/converter started resource="BGPPeer (custom)"
2018-04-06 01:21:19.072 [INFO][81] watchercache.go 127: Starting watch sync/resync processing ListRoot="/calico/resources/v3/projectcalico.org/bgpconfigurations"
2018-04-06 01:21:19.072 [INFO][81] watchercache.go 129: Stopping previous watcher ListRoot="/calico/resources/v3/projectcalico.org/bgpconfigurations"
2018-04-06 01:21:19.072 [INFO][81] watchersyncer.go 153: Error received in main syncer event processing loop error=watch terminated (closedByRemote:true): terminating error event from Kubernetes watcher: closed by remote
2018-04-06 01:21:19.072 [INFO][81] watcher.go 124: Watch event indicates a terminated watcher resource="BGPConfiguration (custom)"
2018-04-06 01:21:19.072 [INFO][81] watcher.go 85: Kubernetes watcher/converter stopped, closing result channel resource="BGPConfiguration (custom)"
2018-04-06 01:21:19.073 [INFO][81] watcher.go 83: Kubernetes watcher/converter started resource="BGPConfiguration (custom)"
2018-04-06 01:21:26.000 [INFO][81] watcher.go 124: Watch event indicates a terminated watcher resource="IPPool (custom)"
2018-04-06 01:21:26.000 [INFO][81] watcher.go 85: Kubernetes watcher/converter stopped, closing result channel resource="IPPool (custom)"
2018-04-06 01:21:26.000 [INFO][81] watchercache.go 127: Starting watch sync/resync processing ListRoot="/calico/resources/v3/projectcalico.org/ippools"
2018-04-06 01:21:26.000 [INFO][81] watchercache.go 129: Stopping previous watcher ListRoot="/calico/resources/v3/projectcalico.org/ippools"
2018-04-06 01:21:26.000 [INFO][81] watchersyncer.go 153: Error received in main syncer event processing loop error=watch terminated (closedByRemote:true): terminating error event from Kubernetes watcher: closed by remote
2018-04-06 01:21:26.001 [INFO][81] watcher.go 83: Kubernetes watcher/converter started resource="IPPool (custom)"
@rphillips
Copy link
Contributor

Did you figure this out @weikinhuang ?

@weikinhuang
Copy link
Contributor Author

weikinhuang commented Apr 6, 2018 •
edited
Loading

@rphillips I figured out the TLS error, it's from haproxy ssl-hello-chk only supporting sslv3 and apiserver now only supports tls1.2. This caused the apiserver lb (haproxy) to disconnect calico. I changed it to a tcp-check to fix that issue. However I'm getting
a different issue now with apiserver (where the haproxy api server is on) and calico happening every few seconds. This is not happening on the other nodes' apiservers where there are masters running.

W0406 14:04:02.411143       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes d83bf183-3946-11e8-93e1-000c2903e197 84942 0 2018-04-06 03:01:47 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
W0406 14:04:12.421469       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes d83bf183-3946-11e8-93e1-000c2903e197 84963 0 2018-04-06 03:01:47 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
W0406 14:04:22.432126       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes d83bf183-3946-11e8-93e1-000c2903e197 84983 0 2018-04-06 03:01:47 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
W0406 14:04:32.442542       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes d83bf183-3946-11e8-93e1-000c2903e197 85004 0 2018-04-06 03:01:47 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
W0406 14:04:42.453510       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes d83bf183-3946-11e8-93e1-000c2903e197 85025 0 2018-04-06 03:01:47 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
W0406 14:04:52.462752       1 mastercount.go:135] Resetting endpoints for master service "kubernetes" to &{{ } {kubernetes  default /api/v1/namespaces/default/endpoints/kubernetes d83bf183-3946-11e8-93e1-000c2903e197 85045 0 2018-04-06 03:01:47 +0000 UTC <nil> <nil> map[] map[] [] nil [] } [{[{192.168.1.191  <nil> <nil>}] [] [{https 6443 TCP}]}]}
W0406 14:05:02.473849 

2018-04-06 17:46:17.945 [INFO][78] watcher.go 124: Watch event indicates a terminated watcher resource="BGPPeer (custom)"
2018-04-06 17:46:17.945 [INFO][78] watcher.go 85: Kubernetes watcher/converter stopped, closing result channel resource="BGPPeer (custom)"
2018-04-06 17:46:17.946 [INFO][78] watcher.go 83: Kubernetes watcher/converter started resource="BGPPeer (custom)"
2018-04-06 17:46:18.642 [INFO][78] watcher.go 124: Watch event indicates a terminated watcher resource="BGPConfiguration (custom)"
2018-04-06 17:46:18.642 [INFO][78] watcher.go 85: Kubernetes watcher/converter stopped, closing result channel resource="BGPConfiguration (custom)"
2018-04-06 17:46:18.642 [INFO][78] watchercache.go 127: Starting watch sync/resync processing ListRoot="/calico/resources/v3/projectcalico.org/bgpconfigurations"
2018-04-06 17:46:18.642 [INFO][78] watchercache.go 129: Stopping previous watcher ListRoot="/calico/resources/v3/projectcalico.org/bgpconfigurations"
2018-04-06 17:46:18.642 [INFO][78] watchersyncer.go 153: Error received in main syncer event processing loop error=watch terminated (closedByRemote:true): terminating error event from Kubernetes watcher: closed by remote
2018-04-06 17:46:18.643 [INFO][78] watcher.go 83: Kubernetes watcher/converter started resource="BGPConfiguration (custom)"
2018-04-06 17:47:10.714 [INFO][78] watcher.go 124: Watch event indicates a terminated watcher resource="IPPool (custom)"
2018-04-06 17:47:10.714 [INFO][78] watcher.go 85: Kubernetes watcher/converter stopped, closing result channel resource="IPPool (custom)"
2018-04-06 17:47:10.714 [INFO][78] watchercache.go 127: Starting watch sync/resync processing ListRoot="/calico/resources/v3/projectcalico.org/ippools"
2018-04-06 17:47:10.714 [INFO][78] watchercache.go 129: Stopping previous watcher ListRoot="/calico/resources/v3/projectcalico.org/ippools"
2018-04-06 17:47:10.715 [INFO][78] watchersyncer.go 153: Error received in main syncer event processing loop error=watch terminated (closedByRemote:true): terminating error event from Kubernetes watcher: closed by remote
2018-04-06 17:47:10.715 [INFO][78] watcher.go 83: Kubernetes watcher/converter started resource="IPPool (custom)"
2018-04-06 17:47:21.280 [INFO][78] watcher.go 124: Watch event indicates a terminated watcher resource="BGPPeer (custom)"
2018-04-06 17:47:21.280 [INFO][78] watcher.go 85: Kubernetes watcher/converter stopped, closing result channel resource="BGPPeer (custom)"
2018-04-06 17:47:21.280 [INFO][78] watchercache.go 127: Starting watch sync/resync processing ListRoot="/calico/resources/v3/projectcalico.org/bgppeers"
2018-04-06 17:47:21.280 [INFO][78] watchercache.go 129: Stopping previous watcher ListRoot="/calico/resources/v3/projectcalico.org/bgppeers"
2018-04-06 17:47:21.280 [INFO][78] watchersyncer.go 153: Error received in main syncer event processing loop error=watch terminated (closedByRemote:true): terminating error event from Kubernetes watcher: closed by remote
2018-04-06 17:47:21.281 [INFO][78] watcher.go 83: Kubernetes watcher/converter started resource="BGPPeer (custom)"
2018-04-06 17:47:48.080 [INFO][78] watcher.go 124: Watch event indicates a terminated watcher resource="BGPConfiguration (custom)"
2018-04-06 17:47:48.080 [INFO][78] watcher.go 85: Kubernetes watcher/converter stopped, closing result channel resource="BGPConfiguration (custom)"
2018-04-06 17:47:48.080 [INFO][78] watchercache.go 127: Starting watch sync/resync processing ListRoot="/calico/resources/v3/projectcalico.org/bgpconfigurations"
2018-04-06 17:47:48.081 [INFO][78] watchercache.go 129: Stopping previous watcher ListRoot="/calico/resources/v3/projectcalico.org/bgpconfigurations"
2018-04-06 17:47:48.080 [INFO][78] watchersyncer.go 153: Error received in main syncer event processing loop error=watch terminated (closedByRemote:true): terminating error event from Kubernetes watcher: closed by remote

@weikinhuang
Copy link
Contributor Author

This is the haproxy conf i'm using

    global
      log /dev/log    local0 info alert
      log /dev/log    local1 notice alert

      pidfile         /var/run/haproxy.pid

      maxconn  8000

      # user bindings
      group nobody
      user nobody
      unix-bind user nobody group nobody

    defaults
      balance   roundrobin
      log       global
      maxconn   8000

      # ignore dns lookups on boot, never fail on address resolution
      default-server  init-addr last,libc,none

      # tcp options
      option dontlognull
      option splice-response
      option http-keep-alive
      option clitcpka
      option srvtcpka
      option tcp-smart-accept
      option tcp-smart-connect
      option contstats

      # http options
      option redispatch

      retries 100
      stats   enable

      timeout http-request    10s
      timeout http-keep-alive 10s
      timeout connect         10s
      timeout client          6h
      timeout client-fin      60s
      timeout tunnel          6h         # timeout to use with WebSocket and CONNECT
      timeout server          6h
      timeout tarpit          15s
      timeout queue           60s
      timeout check           10s

    listen kube-apiserver
      bind 192.168.1.191:6444
      mode tcp
      option tcp-check

      server n001 127.0.0.1:6443 weight 100 check
      server n002 192.168.1.192:6443 weight 1 check backup
      server n003 192.168.1.193:6443 weight 1 check backup

@weikinhuang
Copy link
Contributor Author

weikinhuang commented Apr 6, 2018 •
edited
Loading

Ah looks like a HA config issue with api server, now that i'm on v1.10.0 i can turn on --endpoint-reconciler-type=lease in apiserver. Seems to have fixed the apiserver issue after reading the docs. Though i'm still getting the calico issue every 10-30 seconds.


2018-04-06 18:50:55.264 [INFO][78] watcher.go 124: Watch event indicates a terminated watcher resource="IPPool (custom)"
2018-04-06 18:50:55.264 [INFO][78] watcher.go 85: Kubernetes watcher/converter stopped, closing result channel resource="IPPool (custom)"
2018-04-06 18:50:55.264 [INFO][78] watchercache.go 127: Starting watch sync/resync processing ListRoot="/calico/resources/v3/projectcalico.org/ippools"
2018-04-06 18:50:55.264 [INFO][78] watchercache.go 129: Stopping previous watcher ListRoot="/calico/resources/v3/projectcalico.org/ippools"
2018-04-06 18:50:55.264 [INFO][78] watchersyncer.go 153: Error received in main syncer event processing loop error=watch terminated (closedByRemote:true): terminating error event from Kubernetes watcher: closed by remote
2018-04-06 18:50:55.265 [INFO][78] watcher.go 83: Kubernetes watcher/converter started resource="IPPool (custom)"

seems to be a non issue? https://github.com/projectcalico/libcalico-go/issues/695

@rphillips
Copy link
Contributor

Just a heads up, the lease endpoint reconciler is still alpha.

@weikinhuang
Copy link
Contributor Author

Yep, I read that. But that's ok, since this is a homelab environment anyways.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@rphillips @weikinhuang