Calico: Calico-node readiness probe fails with SLES 15 SP1 nodes on Azure

Created on 5 Nov 2019  路  14Comments  路  Source: projectcalico/calico

Expected Behavior


Calico v3.8.2 to run successfully on SLES 15 SP1 on Azure.
Is it expected calico to be running on SLES? This OS is not listed as a OS that is expected to be working well here

Current Behavior



calico-node Pod readiness probe fails on the nodes that the calico-typha pod is not running.

Possible Solution


Steps to Reproduce (for bugs)


  1. Create a vanilla Kubernetes cluster with SLES 15 SP1 on Azure with at least 2 worker nodes.
  2. Install the calico in a similar manner to https://github.com/kubernetes/kubernetes/tree/v1.15.4/cluster/addons/calico-policy-controller.
  3. Ensure that the calico pod rediness probe fails with:
$ k -n kube-system describe po calico-node-d2khj
Events:
  Type     Reason     Age                 From                                                             Message
  ----     ------     ----                ----                                                             -------
  Warning  Unhealthy  49m (x18 over 52m)  kubelet, my-vm-suse-85865bcf77-scwkj  Readiness probe failed: calico/node is not ready: felix is not ready: readiness probe reporting 503

k -n kube-system logs calico-node-d2khj                                                                                                                                                                                                                                                                                                                        
2019-11-05 16:00:50.113 [INFO][8] startup.go 256: Early log level set to info
2019-11-05 16:00:50.113 [INFO][8] startup.go 272: Using NODENAME environment for node name
2019-11-05 16:00:50.113 [INFO][8] startup.go 284: Determined node name: my-vm--local-az-worker-suse-85865bcf77-scwkj
2019-11-05 16:00:50.114 [INFO][8] k8s.go 219: Using host-local IPAM
2019-11-05 16:00:50.114 [INFO][8] startup.go 316: Checking datastore connection
2019-11-05 16:00:50.203 [INFO][8] startup.go 340: Datastore connection verified
2019-11-05 16:00:50.203 [INFO][8] startup.go 95: Datastore is ready
2019-11-05 16:00:50.322 [INFO][8] startup.go 530: FELIX_IPV6SUPPORT is false through environment variable
2019-11-05 16:00:50.368 [INFO][8] startup.go 181: Using node name: my-vm-suse-85865bcf77-scwkj
2019-11-05 16:00:50.395 [INFO][22] k8s.go 219: Using host-local IPAM
CALICO_NETWORKING_BACKEND is none - no BGP daemon running
Calico node started successfully
2019-11-05 16:56:41.721 [ERROR][45] sync_client.go 260: Failed to read from server address="100.71.169.3:5473" connID=0x0 error=EOF type=""
2019-11-05 16:56:43.721 [FATAL][45] daemon.go 641: Exiting. reason="Connection to Typha failed"
2019-11-05 16:56:45.041 [ERROR][6241] daemon.go 446: Failed to connect to Typha. Retrying... error=dial tcp 100.71.169.3:5473: connect: connection refused
2019-11-05 16:57:24.130 [ERROR][6241] sync_client.go 260: Failed to read from server address="100.71.169.3:5473" connID=0x0 error=read tcp 10.250.0.5:65454->100.71.169.3:5473: i/o timeout type=""                                                                                                                                                                 
2019-11-05 16:57:26.131 [FATAL][6241] daemon.go 641: Exiting. reason="Connection to Typha failed"
2019-11-05 16:57:56.469 [ERROR][6354] sync_client.go 260: Failed to read from server address="100.71.169.3:5473" connID=0x0 error=read tcp 10.250.0.5:32838->100.71.169.3:5473: i/o timeout type=""                                                                                                                                                                 
2019-11-05 16:57:58.469 [FATAL][6354] daemon.go 641: Exiting. reason="Connection to Typha failed"
2019-11-05 16:58:28.719 [ERROR][6435] sync_client.go 260: Failed to read from server address="100.71.169.3:5473" connID=0x0 error=read tcp 10.250.0.5:32996->100.71.169.3:5473: i/o timeout type=""                                                                                                                                                                 
2019-11-05 16:58:30.719 [FATAL][6435] daemon.go 641: Exiting. reason="Connection to Typha failed"
2019-11-05 16:59:00.964 [ERROR][6516] sync_client.go 260: Failed to read from server address="100.71.169.3:5473" connID=0x0 error=read tcp 10.250.0.5:33134->100.71.169.3:5473: i/o timeout type=""                                                                                                                                                                 
2019-11-05 16:59:02.964 [FATAL][6516] daemon.go 641: Exiting. reason="Connection to Typha failed"
2019-11-05 16:59:33.221 [ERROR][6597] sync_client.go 260: Failed to read from server address="100.71.169.3:5473" connID=0x0 error=read tcp 10.250.0.5:33290->100.71.169.3:5473: i/o timeout type=""                                                                                                                                                                 
2019-11-05 16:59:35.222 [FATAL][6597] daemon.go 641: Exiting. reason="Connection to Typha failed"

Context


As this cluster is running on Azure, the following environment variables are used

FELIX_IPINIPENABLED=false
CALICO_NETWORKING_BACKEND=none
CALICO_IPV4POOL_IPIP=Never

Some details about the nodes:

$ k get node -o wide
NAME                          STATUS   ROLES    AGE    VERSION   INTERNAL-IP   EXTERNAL-IP   OS-IMAGE                              KERNEL-VERSION           CONTAINER-RUNTIME
my-vm-suse-85865bcf77-rns74   Ready    <none>   140m   v1.15.4   10.250.0.7    <none>        SUSE Linux Enterprise Server 15 SP1   4.12.14-197.21-default   docker://19.3.1
my-vm-suse-85865bcf77-scwkj   Ready    <none>   140m   v1.15.4   10.250.0.5    <none>        SUSE Linux Enterprise Server 15 SP1   4.12.14-197.21-default   docker://19.3.1

The very same cluster setup works fine if the OS is Ubuntu 18.04 or CoreOS 2135.6.0.

Your Environment

  • Calico version - v3.8.2
  • Orchestrator version (e.g. kubernetes, mesos, rkt): v1.15.4
  • Operating System and version:
$ cat /etc/os-release
NAME="SLES"
VERSION="15-SP1"
VERSION_ID="15.1"
PRETTY_NAME="SUSE Linux Enterprise Server 15 SP1"
ID="sles"
ID_LIKE="suse"
ANSI_COLOR="0;32"
CPE_NAME="cpe:/o:suse:sles:15:sp1"
  • Link to your project (optional):
help wanted kinenhancement
Source
picture vpnachev
👍2 👀1

Most helpful comment

SLES isn't one of the distros that we actively test with. I'd recommend sticking to one of our supported platforms (Ubuntu/RH/Centos). Failing that, look for different routing/iptables set-up on SLES that's blocking that traffic.

picture fasaxc on 11 Nov 2019
👍2

All 14 comments

We have disabled typha, which should mean that calico-node pods now talks directly with k8s API server instead of going through typha. The result is that the cluster is fully functional now, it even has passed the k8s conformance tests.

vpnachev picture vpnachev on 6 Nov 2019

A few more findings.
This behaviour is observed on Google Cloud Platform, as well.

I have created another cluster that has 2 SUSE nodes, 2 CoreOS nodes and calico-typha is enabled.

  1. When typha is running on a SUSE node I observe:

    • the calico-node on the same SUSE node has a successful readiness probe.

    • the calico-node on the other SUSE node has a failing readiness probe.

    • the calico-nodes on the CoreOS nodes have a successful readiness probe.

  2. When typha is running on a CoreOS node I observe:

    • the calico-nodes on every node have a successful readiness probe.

Where should I dig further, calico, typha or both?

vpnachev picture vpnachev on 7 Nov 2019

@caseydavenport / @fasaxc can you provide feedback on this one?

zanetworker picture zanetworker on 11 Nov 2019

SLES isn't one of the distros that we actively test with. I'd recommend sticking to one of our supported platforms (Ubuntu/RH/Centos). Failing that, look for different routing/iptables set-up on SLES that's blocking that traffic.

fasaxc picture fasaxc on 11 Nov 2019
👍2

@fasaxc thanks for the reply.

zanetworker picture zanetworker on 11 Nov 2019

I'd suggest looking at kube-proxy status and logs since it sets up the routing for the kubernetes service for typha, I am guessing that might be broken on SLES and that is why the nodes running on nodes without typha are not going ready.

tmjd picture tmjd on 11 Nov 2019

@tmjd Actually, we bypass kube-proxy for accessing typha. Felix loads the service endpoints from the API server directly and picks one to connect to. That avoids relying on kube-proxy for bootstrapping Calico.

Typha is a host-networked pod, check that your iptables policy on SLES allows traffic to the host from the other hosts on Typha's port.

fasaxc picture fasaxc on 12 Nov 2019

I do not see any issues in the kube-proxy logs.

The communication from node to typha seems to be open

$  nc -v -z 100.71.169.3 5473                                                                                 
100.71.169.3: inverse host lookup failed: Unknown host
(UNKNOWN) [100.71.169.3] 5473 (?) open

$  mtr -P 5473 -T -w 100.71.169.3                                                                             
Start: 2019-11-12T16:51:50+0000
HOST: local-az-worker-suse-84f78947bf-hlsbt Loss%   Snt   Last   Avg  Best  Wrst StDev                                                                   
  1.|-- 100.71.169.3                                            0.0%    10    1.1   1.0   0.8   1.3   0.1

$ mtr --tcp  --port 5473 --report --report-cycles 10 100.71.169.3                                            
Start: 2019-11-12T16:55:33+0000
HOST: local-az-w Loss%   Snt   Last   Avg  Best  Wrst StDev
  1.|-- 100.71.169.3               0.0%    10    0.9   0.9   0.7   1.1   0.1

$ telnet 100.71.169.3 5473                                                                                   
Trying 100.71.169.3...
Connected to 100.71.169.3.
Escape character is '^]'.
^]
telnet> Connection closed.

$ nmap 100.71.169.3 -p 5473 -Pn                                                                              
Starting Nmap 7.70 ( https://nmap.org ) at 2019-11-12 17:01 UTC
Nmap scan report for 100.71.169.3
Host is up.

PORT     STATE    SERVICE
5473/tcp filtered apsolab-tags

Nmap done: 1 IP address (1 host up) scanned in 2.19 seconds

Note, nmap output is identical to a cluster with CoreOS nodes. So I think that there is connectivity between the calico-node and calico-typha.

Let me provide some logs from the VM that is not hosting the Calico Typha.

calico-typha logs

2019-11-12 15:47:45.122 [INFO][6] sync_server.go 373: New connection connID=0x144 port=5473
2019-11-12 15:47:45.122 [INFO][6] sync_server.go 531: Per-connection goroutine started client=10.250.0.4:46700 connID=0x144
2019-11-12 15:47:45.127 [INFO][6] sync_server.go 656: Received Hello message from client. client=10.250.0.4:46700 connID=0x144 msg=syncproto.MsgClientHello{Hostname:"local-az-worker-suse-84f78947bf-hlsbt", Info:"Revision: a161671c667ac33d85736944e9aa069995498911; Build date: ", Version:"v3.8.2", SyncerType:"felix"}
2019-11-12 15:47:45.127 [INFO][6] sync_server.go 561: Waiting for messages from client client=10.250.0.4:46700 connID=0x144
2019-11-12 15:47:45.127 [INFO][6] sync_server.go 825: Starting to send snapshot to client client=10.250.0.4:46700 connID=0x144 seqNo=0x7 status=in-sync thread="kv-sender"
2019-11-12 15:47:45.128 [INFO][6] sync_server.go 859: Finished sending snapshot to client client=10.250.0.4:46700 connID=0x144 numKeys=79 seqNo=0x7 status=in-sync thread="kv-sender"
2019-11-12 15:47:45.128 [INFO][6] sync_server.go 726: Status update to send. client=10.250.0.4:46700 connID=0x144 newStatus=in-sync thread="kv-sender"
2019-11-12 15:48:15.130 [INFO][6] sync_server.go 609: Failed to read from client client=10.250.0.4:46700 connID=0x144 error=EOF thread="read"
2019-11-12 15:48:15.130 [INFO][6] sync_server.go 602: Read goroutine finished client=10.250.0.4:46700 connID=0x144 thread="read"
2019-11-12 15:48:15.130 [INFO][6] sync_server.go 589: Asked to stop by Context. client=10.250.0.4:46700 connID=0x144
2019-11-12 15:48:15.130 [INFO][6] sync_server.go 555: Stopping pong check ticker. client=10.250.0.4:46700 connID=0x144
2019-11-12 15:48:15.130 [INFO][6] sync_server.go 903: Context was canceled. error=context canceled
2019-11-12 15:48:15.130 [INFO][6] sync_server.go 888: Stopping ping ticker client=10.250.0.4:46700 connID=0x144 thread="pinger"
2019-11-12 15:48:15.130 [INFO][6] sync_server.go 884: Pinger goroutine shut down. client=10.250.0.4:46700 connID=0x144 thread="pinger"
2019-11-12 15:48:15.131 [INFO][6] sync_server.go 518: Client connection shutting down. client=10.250.0.4:46700 connID=0x144
2019-11-12 15:48:15.131 [INFO][6] jittered_ticker.go 57: Stopping jittered ticker
2019-11-12 15:48:15.131 [INFO][6] jittered_ticker.go 57: Stopping jittered ticker
2019-11-12 15:48:15.457 [INFO][6] sync_server.go 755: Getting next Breadcrumb canceled by context. client=10.250.0.4:46700 connID=0x144 error=context canceled thread="kv-sender"
2019-11-12 15:48:15.457 [INFO][6] sync_server.go 708: KV-sender goroutine shutting down client=10.250.0.4:46700 connID=0x144 thread="kv-sender"
2019-11-12 15:48:15.457 [INFO][6] sync_server.go 711: KV-sender goroutine finished client=10.250.0.4:46700 connID=0x144 thread="kv-sender"
2019-11-12 15:48:15.457 [INFO][6] sync_server.go 527: Client connection shut down. client=10.250.0.4:46700 connID=0x144
2019-11-12 15:48:15.457 [INFO][6] sync_server.go 401: Connection handler finished error=context canceled
2019-11-12 15:48:17.501 [INFO][6] sync_server.go 348: Accepted from 10.250.0.4:46850 port=5473

calico-node logs

Calico Node Logs 



2019-11-12 15:47:44.549 [INFO][19004] logutils.go 82: Early screen log level set to info
2019-11-12 15:47:44.549 [INFO][19004] daemon.go 138: Felix starting up GOMAXPROCS=2 buildDate="" gitCommit="a161671c667ac33d85736944e9aa069995498911" version="v3.8.2"
2019-11-12 15:47:44.549 [INFO][19004] daemon.go 156: Loading configuration...
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "ipv6support"="false"
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "felixhostname"="local-az-worker-suse-84f78947bf-hlsbt"
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "ipinipenabled"="false"
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "typhak8sservicename"="calico-typha"
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "natportrange"="32768:65535"
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "etcdcertfile"=""
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "logseverityscreen"="info"
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "etcdscheme"=""
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "defaultendpointtohostaction"="ACCEPT"
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "etcdaddr"=""
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "datastoretype"="kubernetes"
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "etcdkeyfile"=""
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "healthenabled"="true"
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "ipinipmtu"="1440"
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "etcdendpoints"=""
2019-11-12 15:47:44.551 [INFO][19004] env_var_loader.go 40: Found felix environment variable: "etcdcafile"=""
2019-11-12 15:47:44.551 [INFO][19004] daemon.go 179: Loading config file: /etc/calico/felix.cfg
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 243: Merging in config from environment variable: map[felixhostname:local-az-worker-suse-84f78947bf-hlsbt healthenabled:true ipinipmtu:1440 etcdendpoints: ipv6support:false typhak8sservicename:calico-typha etcdcertfile: etcdaddr: datastoretype:kubernetes etcdcafile: natportrange:32768:65535 logseverityscreen:info etcdscheme: etcdkeyfile: ipinipenabled:false defaultendpointtohostaction:ACCEPT]
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 252: Ignoring empty configuration parameter. Use value 'none' if your intention is to explicitly disable the default value. name="etcdcertfile" source=environment variable
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 252: Ignoring empty configuration parameter. Use value 'none' if your intention is to explicitly disable the default value. name="etcdaddr" source=environment variable
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 252: Ignoring empty configuration parameter. Use value 'none' if your intention is to explicitly disable the default value. name="etcdcafile" source=environment variable
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 252: Ignoring empty configuration parameter. Use value 'none' if your intention is to explicitly disable the default value. name="etcdscheme" source=environment variable
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 252: Ignoring empty configuration parameter. Use value 'none' if your intention is to explicitly disable the default value. name="etcdkeyfile" source=environment variable
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 252: Ignoring empty configuration parameter. Use value 'none' if your intention is to explicitly disable the default value. name="etcdendpoints" source=environment variable
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 324: Parsing value for FelixHostname: local-az-worker-suse-84f78947bf-hlsbt (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 360: Parsed value for FelixHostname: local-az-worker-suse-84f78947bf-hlsbt (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 324: Parsing value for HealthEnabled: true (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 360: Parsed value for HealthEnabled: true (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 324: Parsing value for IpInIpMtu: 1440 (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 360: Parsed value for IpInIpMtu: 1440 (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 324: Parsing value for TyphaK8sServiceName: calico-typha (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 360: Parsed value for TyphaK8sServiceName: calico-typha (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 324: Parsing value for DatastoreType: kubernetes (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 360: Parsed value for DatastoreType: kubernetes (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 324: Parsing value for NATPortRange: 32768:65535 (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 360: Parsed value for NATPortRange: 32768:65535 (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 324: Parsing value for LogSeverityScreen: info (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 360: Parsed value for LogSeverityScreen: INFO (from environment variable)
2019-11-12 15:47:44.552 [INFO][19004] config_params.go 324: Parsing value for IpInIpEnabled: false (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 360: Parsed value for IpInIpEnabled: false (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 324: Parsing value for Ipv6Support: false (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 360: Parsed value for Ipv6Support: false (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 324: Parsing value for DefaultEndpointToHostAction: ACCEPT (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 360: Parsed value for DefaultEndpointToHostAction: ACCEPT (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 243: Merging in config from config file: map[MetadataAddr:None LogFilePath:None LogSeverityFile:None LogSeveritySys:None]
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 324: Parsing value for DatastoreType: kubernetes (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 360: Parsed value for DatastoreType: kubernetes (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 324: Parsing value for NATPortRange: 32768:65535 (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 360: Parsed value for NATPortRange: 32768:65535 (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 324: Parsing value for LogSeverityScreen: info (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 360: Parsed value for LogSeverityScreen: INFO (from environment variable)
2019-11-12 15:47:44.553 [INFO][19004] config_params.go 324: Parsing value for IpInIpEnabled: false (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 360: Parsed value for IpInIpEnabled: false (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 324: Parsing value for FelixHostname: local-az-worker-suse-84f78947bf-hlsbt (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 360: Parsed value for FelixHostname: local-az-worker-suse-84f78947bf-hlsbt (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 324: Parsing value for HealthEnabled: true (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 360: Parsed value for HealthEnabled: true (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 324: Parsing value for IpInIpMtu: 1440 (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 360: Parsed value for IpInIpMtu: 1440 (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 324: Parsing value for TyphaK8sServiceName: calico-typha (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 360: Parsed value for TyphaK8sServiceName: calico-typha (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 324: Parsing value for DefaultEndpointToHostAction: ACCEPT (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 360: Parsed value for DefaultEndpointToHostAction: ACCEPT (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 324: Parsing value for Ipv6Support: false (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 360: Parsed value for Ipv6Support: false (from environment variable)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 324: Parsing value for MetadataAddr: None (from config file)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 360: Parsed value for MetadataAddr:  (from config file)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 324: Parsing value for LogFilePath: None (from config file)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 360: Parsed value for LogFilePath:  (from config file)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 324: Parsing value for LogSeverityFile: None (from config file)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 360: Parsed value for LogSeverityFile:  (from config file)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 324: Parsing value for LogSeveritySys: None (from config file)
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.554 [INFO][19004] config_params.go 360: Parsed value for LogSeveritySys:  (from config file)
2019-11-12 15:47:44.555 [INFO][19004] health.go 225: Health enabled.  Starting server. host="localhost" port=9099
2019-11-12 15:47:44.555 [INFO][19004] config_params.go 428: Encap disabled, disabling node poll (if KDD is in use).
2019-11-12 15:47:44.555 [INFO][19004] daemon.go 211: Connecting to datastore datastore="kubernetes"
2019-11-12 15:47:44.557 [INFO][19004] k8s.go 219: Using host-local IPAM
2019-11-12 15:47:44.557 [INFO][19004] daemon.go 218: Created datastore client
2019-11-12 15:47:44.645 [INFO][19004] daemon.go 771: Loaded ready flag kind="ClusterInformation" name="default" ready=true
2019-11-12 15:47:44.690 [INFO][19004] daemon.go 751: No config of this type kind="FelixConfiguration" name="node.local-az-worker-suse-84f78947bf-hlsbt"
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 243: Merging in config from datastore (global): map[ClusterGUID:5075b44df893404da853f337a40d18a1 ClusterType:k8s,bgp,kdd,typha CalicoVersion:v3.8.2 LogSeverityScreen:Info ReportingIntervalSecs:0]
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 324: Parsing value for DatastoreType: kubernetes (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 360: Parsed value for DatastoreType: kubernetes (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 324: Parsing value for NATPortRange: 32768:65535 (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 360: Parsed value for NATPortRange: 32768:65535 (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 324: Parsing value for LogSeverityScreen: info (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 360: Parsed value for LogSeverityScreen: INFO (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 324: Parsing value for IpInIpEnabled: false (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 360: Parsed value for IpInIpEnabled: false (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 324: Parsing value for FelixHostname: local-az-worker-suse-84f78947bf-hlsbt (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 360: Parsed value for FelixHostname: local-az-worker-suse-84f78947bf-hlsbt (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 324: Parsing value for HealthEnabled: true (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 360: Parsed value for HealthEnabled: true (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 324: Parsing value for IpInIpMtu: 1440 (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 360: Parsed value for IpInIpMtu: 1440 (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 324: Parsing value for TyphaK8sServiceName: calico-typha (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 360: Parsed value for TyphaK8sServiceName: calico-typha (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 324: Parsing value for DefaultEndpointToHostAction: ACCEPT (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 360: Parsed value for DefaultEndpointToHostAction: ACCEPT (from environment variable)
2019-11-12 15:47:44.714 [INFO][19004] config_params.go 324: Parsing value for Ipv6Support: false (from environment variable)
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 360: Parsed value for Ipv6Support: false (from environment variable)
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 324: Parsing value for LogSeveritySys: None (from config file)
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 360: Parsed value for LogSeveritySys:  (from config file)
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 324: Parsing value for MetadataAddr: None (from config file)
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 360: Parsed value for MetadataAddr:  (from config file)
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 324: Parsing value for LogFilePath: None (from config file)
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 360: Parsed value for LogFilePath:  (from config file)
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 324: Parsing value for LogSeverityFile: None (from config file)
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 360: Parsed value for LogSeverityFile:  (from config file)
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 324: Parsing value for ReportingIntervalSecs: 0 (from datastore (global))
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 360: Parsed value for ReportingIntervalSecs: 0s (from datastore (global))
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 324: Parsing value for ClusterGUID: 5075b44df893404da853f337a40d18a1 (from datastore (global))
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 360: Parsed value for ClusterGUID: 5075b44df893404da853f337a40d18a1 (from datastore (global))
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 324: Parsing value for ClusterType: k8s,bgp,kdd,typha (from datastore (global))
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 360: Parsed value for ClusterType: k8s,bgp,kdd,typha (from datastore (global))
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 324: Parsing value for CalicoVersion: v3.8.2 (from datastore (global))
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 360: Parsed value for CalicoVersion: v3.8.2 (from datastore (global))
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 324: Parsing value for LogSeverityScreen: Info (from datastore (global))
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 360: Parsed value for LogSeverityScreen: INFO (from datastore (global))
2019-11-12 15:47:44.715 [INFO][19004] config_params.go 363: Skipping config value for LogSeverityScreen from datastore (global); already have a value from environment variable
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 243: Merging in config from datastore (per-host): map[IpInIpTunnelAddr:100.96.1.1]
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 324: Parsing value for Ipv6Support: false (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 360: Parsed value for Ipv6Support: false (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 324: Parsing value for DefaultEndpointToHostAction: ACCEPT (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 360: Parsed value for DefaultEndpointToHostAction: ACCEPT (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 324: Parsing value for FelixHostname: local-az-worker-suse-84f78947bf-hlsbt (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 360: Parsed value for FelixHostname: local-az-worker-suse-84f78947bf-hlsbt (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 324: Parsing value for HealthEnabled: true (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 360: Parsed value for HealthEnabled: true (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 324: Parsing value for IpInIpMtu: 1440 (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 360: Parsed value for IpInIpMtu: 1440 (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 324: Parsing value for TyphaK8sServiceName: calico-typha (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 360: Parsed value for TyphaK8sServiceName: calico-typha (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 324: Parsing value for DatastoreType: kubernetes (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 360: Parsed value for DatastoreType: kubernetes (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 324: Parsing value for NATPortRange: 32768:65535 (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 360: Parsed value for NATPortRange: 32768:65535 (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 324: Parsing value for LogSeverityScreen: info (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 360: Parsed value for LogSeverityScreen: INFO (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 324: Parsing value for IpInIpEnabled: false (from environment variable)
2019-11-12 15:47:44.716 [INFO][19004] config_params.go 360: Parsed value for IpInIpEnabled: false (from environment variable)
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 324: Parsing value for MetadataAddr: None (from config file)
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 360: Parsed value for MetadataAddr:  (from config file)
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 324: Parsing value for LogFilePath: None (from config file)
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 360: Parsed value for LogFilePath:  (from config file)
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 324: Parsing value for LogSeverityFile: None (from config file)
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 360: Parsed value for LogSeverityFile:  (from config file)
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 324: Parsing value for LogSeveritySys: None (from config file)
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 341: Value set to 'none', replacing with zero-value: "".
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 360: Parsed value for LogSeveritySys:  (from config file)
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 324: Parsing value for IpInIpTunnelAddr: 100.96.1.1 (from datastore (per-host))
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 360: Parsed value for IpInIpTunnelAddr: 100.96.1.1 (from datastore (per-host))
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 324: Parsing value for ReportingIntervalSecs: 0 (from datastore (global))
2019-11-12 15:47:44.717 [INFO][19004] config_params.go 360: Parsed value for ReportingIntervalSecs: 0s (from datastore (global))
2019-11-12 15:47:44.718 [INFO][19004] config_params.go 324: Parsing value for ClusterGUID: 5075b44df893404da853f337a40d18a1 (from datastore (global))
2019-11-12 15:47:44.718 [INFO][19004] config_params.go 360: Parsed value for ClusterGUID: 5075b44df893404da853f337a40d18a1 (from datastore (global))
2019-11-12 15:47:44.718 [INFO][19004] config_params.go 324: Parsing value for ClusterType: k8s,bgp,kdd,typha (from datastore (global))
2019-11-12 15:47:44.718 [INFO][19004] config_params.go 360: Parsed value for ClusterType: k8s,bgp,kdd,typha (from datastore (global))
2019-11-12 15:47:44.718 [INFO][19004] config_params.go 324: Parsing value for CalicoVersion: v3.8.2 (from datastore (global))
2019-11-12 15:47:44.719 [INFO][19004] config_params.go 360: Parsed value for CalicoVersion: v3.8.2 (from datastore (global))
2019-11-12 15:47:44.719 [INFO][19004] config_params.go 324: Parsing value for LogSeverityScreen: Info (from datastore (global))
2019-11-12 15:47:44.719 [INFO][19004] config_params.go 360: Parsed value for LogSeverityScreen: INFO (from datastore (global))
2019-11-12 15:47:44.719 [INFO][19004] config_params.go 363: Skipping config value for LogSeverityScreen from datastore (global); already have a value from environment variable
2019-11-12 15:47:44.719 [INFO][19004] config_params.go 428: Encap disabled, disabling node poll (if KDD is in use).
2019-11-12 15:47:44.720 [INFO][19004] k8s.go 219: Using host-local IPAM
2019-11-12 15:47:44.744 [INFO][19004] daemon.go 1022: Found Typha ClusterIP. clusterIP="100.71.169.3"
2019-11-12 15:47:44.744 [INFO][19004] daemon.go 1029: Found Typha service port. port=v1.ServicePort{Name:"calico-typha", Protocol:"TCP", Port:5473, TargetPort:intstr.IntOrString{Type:1, IntVal:0, StrVal:"calico-typha"}, NodePort:31939}
2019-11-12 15:47:44.744 [INFO][19004] health.go 222: Health enabled.  Server is already running. host="localhost" port=9099
2019-11-12 15:47:44.744 [INFO][19004] daemon.go 286: Successfully loaded configuration. GOMAXPROCS=2 buildDate="" config=&config.Config{UseInternalDataplaneDriver:true, DataplaneDriver:"calico-iptables-plugin", DatastoreType:"kubernetes", FelixHostname:"local-az-worker-suse-84f78947bf-hlsbt", EtcdAddr:"127.0.0.1:2379", EtcdScheme:"http", EtcdKeyFile:"", EtcdCertFile:"", EtcdCaFile:"", EtcdEndpoints:[]string(nil), TyphaAddr:"", TyphaK8sServiceName:"calico-typha", TyphaK8sNamespace:"kube-system", TyphaReadTimeout:30000000000, TyphaWriteTimeout:10000000000, TyphaKeyFile:"", TyphaCertFile:"", TyphaCAFile:"", TyphaCN:"", TyphaURISAN:"", Ipv6Support:false, IgnoreLooseRPF:false, IptablesBackend:"legacy", RouteRefreshInterval:90000000000, IptablesRefreshInterval:90000000000, IptablesPostWriteCheckIntervalSecs:1000000000, IptablesLockFilePath:"/run/xtables.lock", IptablesLockTimeoutSecs:0, IptablesLockProbeIntervalMillis:50000000, IpsetsRefreshInterval:10000000000, MaxIpsetSize:1048576, XDPRefreshInterval:90000000000, PolicySyncPathPrefix:"", NetlinkTimeoutSecs:10000000000, MetadataAddr:"", MetadataPort:8775, OpenstackRegion:"", InterfacePrefix:"cali", InterfaceExclude:[]*regexp.Regexp{(*regexp.Regexp)(0xc000467900)}, ChainInsertMode:"insert", DefaultEndpointToHostAction:"ACCEPT", IptablesFilterAllowAction:"ACCEPT", IptablesMangleAllowAction:"ACCEPT", LogPrefix:"calico-packet", LogFilePath:"", LogSeverityFile:"", LogSeverityScreen:"INFO", LogSeveritySys:"", VXLANEnabled:false, VXLANPort:4789, VXLANVNI:4096, VXLANMTU:1410, IPv4VXLANTunnelAddr:net.IP(nil), VXLANTunnelMACAddr:"", IpInIpEnabled:false, IpInIpMtu:1440, IpInIpTunnelAddr:net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x64, 0x60, 0x1, 0x1}, ReportingIntervalSecs:0, ReportingTTLSecs:90000000000, EndpointReportingEnabled:false, EndpointReportingDelaySecs:1000000000, IptablesMarkMask:0xffff0000, DisableConntrackInvalidCheck:false, HealthEnabled:true, HealthPort:9099, HealthHost:"localhost", PrometheusMetricsEnabled:false, PrometheusMetricsPort:9091, PrometheusGoMetricsEnabled:true, PrometheusProcessMetricsEnabled:true, FailsafeInboundHostPorts:[]config.ProtoPort{config.ProtoPort{Protocol:"tcp", Port:0x16}, config.ProtoPort{Protocol:"udp", Port:0x44}, config.ProtoPort{Protocol:"tcp", Port:0xb3}, config.ProtoPort{Protocol:"tcp", Port:0x94b}, config.ProtoPort{Protocol:"tcp", Port:0x94c}, config.ProtoPort{Protocol:"tcp", Port:0x1a0a}, config.ProtoPort{Protocol:"tcp", Port:0x1a0b}}, FailsafeOutboundHostPorts:[]config.ProtoPort{config.ProtoPort{Protocol:"udp", Port:0x35}, config.ProtoPort{Protocol:"udp", Port:0x43}, config.ProtoPort{Protocol:"tcp", Port:0xb3}, config.ProtoPort{Protocol:"tcp", Port:0x94b}, config.ProtoPort{Protocol:"tcp", Port:0x94c}, config.ProtoPort{Protocol:"tcp", Port:0x1a0a}, config.ProtoPort{Protocol:"tcp", Port:0x1a0b}}, KubeNodePortRanges:[]numorstring.Port{numorstring.Port{MinPort:0x7530, MaxPort:0x7fff, PortName:""}}, NATPortRange:numorstring.Port{MinPort:0x8000, MaxPort:0xffff, PortName:""}, NATOutgoingAddress:net.IP(nil), UsageReportingEnabled:true, UsageReportingInitialDelaySecs:300000000000, UsageReportingIntervalSecs:86400000000000, ClusterGUID:"5075b44df893404da853f337a40d18a1", ClusterType:"k8s,bgp,kdd,typha", CalicoVersion:"v3.8.2", ExternalNodesCIDRList:[]string(nil), DebugMemoryProfilePath:"", DebugCPUProfilePath:"/tmp/felix-cpu-<timestamp>.pprof", DebugDisableLogDropping:false, DebugSimulateCalcGraphHangAfter:0, DebugSimulateDataplaneHangAfter:0, sourceToRawConfig:map[config.Source]map[string]string{0x4:map[string]string{"typhak8sservicename":"calico-typha", "datastoretype":"kubernetes", "natportrange":"32768:65535", "logseverityscreen":"info", "ipinipenabled":"false", "felixhostname":"local-az-worker-suse-84f78947bf-hlsbt", "healthenabled":"true", "ipinipmtu":"1440", "ipv6support":"false", "defaultendpointtohostaction":"ACCEPT"}, 0x3:map[string]string{"MetadataAddr":"None", "LogFilePath":"None", "LogSeverityFile":"None", "LogSeveritySys":"None"}, 0x1:map[string]string{"CalicoVersion":"v3.8.2", "LogSeverityScreen":"Info", "ReportingIntervalSecs":"0", "ClusterGUID":"5075b44df893404da853f337a40d18a1", "ClusterType":"k8s,bgp,kdd,typha"}, 0x2:map[string]string{"IpInIpTunnelAddr":"100.96.1.1"}}, rawValues:map[string]string{"ReportingIntervalSecs":"0", "CalicoVersion":"v3.8.2", "Ipv6Support":"false", "NATPortRange":"32768:65535", "MetadataAddr":"None", "LogSeverityFile":"None", "IpInIpTunnelAddr":"100.96.1.1", "DatastoreType":"kubernetes", "LogFilePath":"None", "FelixHostname":"local-az-worker-suse-84f78947bf-hlsbt", "IpInIpMtu":"1440", "LogSeverityScreen":"info", "IpInIpEnabled":"false", "ClusterType":"k8s,bgp,kdd,typha", "DefaultEndpointToHostAction":"ACCEPT", "HealthEnabled":"true", "TyphaK8sServiceName":"calico-typha", "LogSeveritySys":"None", "ClusterGUID":"5075b44df893404da853f337a40d18a1"}, Err:error(nil), IptablesNATOutgoingInterfaceFilter:"", SidecarAccelerationEnabled:false, XDPEnabled:false, GenericXDPEnabled:false} gitCommit="a161671c667ac33d85736944e9aa069995498911" version="v3.8.2"
2019-11-12 15:47:44.744 [INFO][19004] driver.go 43: Using internal (linux) dataplane driver.
2019-11-12 15:47:44.745 [INFO][19004] driver.go 85: Calculated iptables mark bits acceptMark=0x10000 endpointMark=0xfff00000 endpointMarkNonCali=0x100000 passMark=0x20000 scratch0Mark=0x40000 scratch1Mark=0x80000
2019-11-12 15:47:44.745 [INFO][19004] int_dataplane.go 238: Creating internal dataplane driver. config=intdataplane.Config{Hostname:"local-az-worker-suse-84f78947bf-hlsbt", IPv6Enabled:false, RuleRendererOverride:rules.RuleRenderer(nil), IPIPMTU:1440, VXLANMTU:1410, IgnoreLooseRPF:false, MaxIPSetSize:1048576, IptablesBackend:"legacy", IPSetsRefreshInterval:10000000000, RouteRefreshInterval:90000000000, IptablesRefreshInterval:90000000000, IptablesPostWriteCheckInterval:1000000000, IptablesInsertMode:"insert", IptablesLockFilePath:"/run/xtables.lock", IptablesLockTimeout:0, IptablesLockProbeInterval:50000000, XDPRefreshInterval:90000000000, NetlinkTimeout:10000000000, RulesConfig:rules.Config{IPSetConfigV4:(*ipsets.IPVersionConfig)(0xc0003a4be0), IPSetConfigV6:(*ipsets.IPVersionConfig)(0xc0003a4cd0), WorkloadIfacePrefixes:[]string{"cali"}, IptablesMarkAccept:0x10000, IptablesMarkPass:0x20000, IptablesMarkScratch0:0x40000, IptablesMarkScratch1:0x80000, IptablesMarkEndpoint:0xfff00000, IptablesMarkNonCaliEndpoint:0x100000, KubeNodePortRanges:[]numorstring.Port{numorstring.Port{MinPort:0x7530, MaxPort:0x7fff, PortName:""}}, KubeIPVSSupportEnabled:false, OpenStackMetadataIP:net.IP(nil), OpenStackMetadataPort:0x2247, OpenStackSpecialCasesEnabled:false, VXLANEnabled:false, VXLANPort:4789, VXLANVNI:4096, IPIPEnabled:false, IPIPTunnelAddress:net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x64, 0x60, 0x1, 0x1}, VXLANTunnelAddress:net.IP(nil), IptablesLogPrefix:"calico-packet", EndpointToHostAction:"ACCEPT", IptablesFilterAllowAction:"ACCEPT", IptablesMangleAllowAction:"ACCEPT", FailsafeInboundHostPorts:[]config.ProtoPort{config.ProtoPort{Protocol:"tcp", Port:0x16}, config.ProtoPort{Protocol:"udp", Port:0x44}, config.ProtoPort{Protocol:"tcp", Port:0xb3}, config.ProtoPort{Protocol:"tcp", Port:0x94b}, config.ProtoPort{Protocol:"tcp", Port:0x94c}, config.ProtoPort{Protocol:"tcp", Port:0x1a0a}, config.ProtoPort{Protocol:"tcp", Port:0x1a0b}}, FailsafeOutboundHostPorts:[]config.ProtoPort{config.ProtoPort{Protocol:"udp", Port:0x35}, config.ProtoPort{Protocol:"udp", Port:0x43}, config.ProtoPort{Protocol:"tcp", Port:0xb3}, config.ProtoPort{Protocol:"tcp", Port:0x94b}, config.ProtoPort{Protocol:"tcp", Port:0x94c}, config.ProtoPort{Protocol:"tcp", Port:0x1a0a}, config.ProtoPort{Protocol:"tcp", Port:0x1a0b}}, DisableConntrackInvalid:false, NATPortRange:numorstring.Port{MinPort:0x8000, MaxPort:0xffff, PortName:""}, IptablesNATOutgoingInterfaceFilter:"", NATOutgoingAddress:net.IP(nil)}, IfaceMonitorConfig:ifacemonitor.Config{InterfaceExcludes:[]*regexp.Regexp{(*regexp.Regexp)(0xc000467900)}}, StatusReportingInterval:0, ConfigChangedRestartCallback:(func())(0x1464ab0), PostInSyncCallback:(func())(0x144b060), HealthAggregator:(*health.HealthAggregator)(0xc0005e3410), DebugSimulateDataplaneHangAfter:0, ExternalNodesCidrs:[]string(nil), XDPEnabled:false, XDPAllowGeneric:false, SidecarAccelerationEnabled:false, LookPathOverride:(func(string) (string, error))(nil)}
2019-11-12 15:47:44.745 [INFO][19004] rule_defs.go 294: Creating rule renderer. config=rules.Config{IPSetConfigV4:(*ipsets.IPVersionConfig)(0xc0003a4be0), IPSetConfigV6:(*ipsets.IPVersionConfig)(0xc0003a4cd0), WorkloadIfacePrefixes:[]string{"cali"}, IptablesMarkAccept:0x10000, IptablesMarkPass:0x20000, IptablesMarkScratch0:0x40000, IptablesMarkScratch1:0x80000, IptablesMarkEndpoint:0xfff00000, IptablesMarkNonCaliEndpoint:0x100000, KubeNodePortRanges:[]numorstring.Port{numorstring.Port{MinPort:0x7530, MaxPort:0x7fff, PortName:""}}, KubeIPVSSupportEnabled:false, OpenStackMetadataIP:net.IP(nil), OpenStackMetadataPort:0x2247, OpenStackSpecialCasesEnabled:false, VXLANEnabled:false, VXLANPort:4789, VXLANVNI:4096, IPIPEnabled:false, IPIPTunnelAddress:net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x64, 0x60, 0x1, 0x1}, VXLANTunnelAddress:net.IP(nil), IptablesLogPrefix:"calico-packet", EndpointToHostAction:"ACCEPT", IptablesFilterAllowAction:"ACCEPT", IptablesMangleAllowAction:"ACCEPT", FailsafeInboundHostPorts:[]config.ProtoPort{config.ProtoPort{Protocol:"tcp", Port:0x16}, config.ProtoPort{Protocol:"udp", Port:0x44}, config.ProtoPort{Protocol:"tcp", Port:0xb3}, config.ProtoPort{Protocol:"tcp", Port:0x94b}, config.ProtoPort{Protocol:"tcp", Port:0x94c}, config.ProtoPort{Protocol:"tcp", Port:0x1a0a}, config.ProtoPort{Protocol:"tcp", Port:0x1a0b}}, FailsafeOutboundHostPorts:[]config.ProtoPort{config.ProtoPort{Protocol:"udp", Port:0x35}, config.ProtoPort{Protocol:"udp", Port:0x43}, config.ProtoPort{Protocol:"tcp", Port:0xb3}, config.ProtoPort{Protocol:"tcp", Port:0x94b}, config.ProtoPort{Protocol:"tcp", Port:0x94c}, config.ProtoPort{Protocol:"tcp", Port:0x1a0a}, config.ProtoPort{Protocol:"tcp", Port:0x1a0b}}, DisableConntrackInvalid:false, NATPortRange:numorstring.Port{MinPort:0x8000, MaxPort:0xffff, PortName:""}, IptablesNATOutgoingInterfaceFilter:"", NATOutgoingAddress:net.IP(nil)}
2019-11-12 15:47:44.745 [INFO][19004] rule_defs.go 304: Workload to host packets will be accepted.
2019-11-12 15:47:44.745 [INFO][19004] rule_defs.go 318: filter table allowed packets will be accepted immediately.
2019-11-12 15:47:44.745 [INFO][19004] rule_defs.go 326: mangle table allowed packets will be accepted immediately.
2019-11-12 15:47:44.748 [INFO][19004] feature_detect.go 110: Updating detected iptables features features=iptables.Features{SNATFullyRandom:true, MASQFullyRandom:true, RestoreSupportsLock:true} iptablesVersion=1.8.2 kernelVersion=4.12.14
2019-11-12 15:47:44.748 [INFO][19004] table.go 444: Looked up iptables command backendMode="legacy" candidates=[]string{"iptables-legacy-restore", "iptables-restore"} command="iptables-legacy-restore" ipVersion=0x4 saveOrRestore="restore"
2019-11-12 15:47:44.748 [INFO][19004] table.go 444: Looked up iptables command backendMode="legacy" candidates=[]string{"iptables-legacy-save", "iptables-save"} command="iptables-legacy-save" ipVersion=0x4 saveOrRestore="save"
2019-11-12 15:47:44.749 [INFO][19004] table.go 444: Looked up iptables command backendMode="legacy" candidates=[]string{"iptables-legacy-restore", "iptables-restore"} command="iptables-legacy-restore" ipVersion=0x4 saveOrRestore="restore"
2019-11-12 15:47:44.749 [INFO][19004] table.go 444: Looked up iptables command backendMode="legacy" candidates=[]string{"iptables-legacy-save", "iptables-save"} command="iptables-legacy-save" ipVersion=0x4 saveOrRestore="save"
2019-11-12 15:47:44.750 [INFO][19004] table.go 444: Looked up iptables command backendMode="legacy" candidates=[]string{"iptables-legacy-restore", "iptables-restore"} command="iptables-legacy-restore" ipVersion=0x4 saveOrRestore="restore"
2019-11-12 15:47:44.750 [INFO][19004] table.go 444: Looked up iptables command backendMode="legacy" candidates=[]string{"iptables-legacy-save", "iptables-save"} command="iptables-legacy-save" ipVersion=0x4 saveOrRestore="save"
2019-11-12 15:47:44.750 [INFO][19004] table.go 444: Looked up iptables command backendMode="legacy" candidates=[]string{"iptables-legacy-restore", "iptables-restore"} command="iptables-legacy-restore" ipVersion=0x4 saveOrRestore="restore"
2019-11-12 15:47:44.750 [INFO][19004] table.go 444: Looked up iptables command backendMode="legacy" candidates=[]string{"iptables-legacy-save", "iptables-save"} command="iptables-legacy-save" ipVersion=0x4 saveOrRestore="save"
2019-11-12 15:47:44.750 [INFO][19004] route_table.go 158: Calculated interface name regexp regex="^cali.*"
2019-11-12 15:47:44.750 [INFO][19004] int_dataplane.go 360: Checking if we need to clean up the VXLAN device
2019-11-12 15:47:44.751 [WARNING][19004] int_dataplane.go 362: Failed to query VXLAN device error=Link not found
2019-11-12 15:47:44.751 [INFO][19004] int_dataplane.go 386: XDP acceleration disabled.
2019-11-12 15:47:44.789 [WARNING][19004] int_dataplane.go 392: Failed to cleanup preexisting XDP state error=failed to load BPF program (/tmp/felix-bpf-658800079): stat /sys/fs/bpf/calico/xdp/prefilter_v1_calico_tmp_A: no such file or directory
2019-11-12 15:47:44.793 [INFO][19004] ipsets.go 119: Queueing IP set for creation family="inet" setID="all-ipam-pools" setType="hash:net"
2019-11-12 15:47:44.793 [INFO][19004] ipsets.go 119: Queueing IP set for creation family="inet" setID="masq-ipam-pools" setType="hash:net"
2019-11-12 15:47:44.793 [INFO][19004] int_dataplane.go 542: Registering to report health.
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-failsafe-in" ipVersion=0x4 table="raw"
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-failsafe-out" ipVersion=0x4 table="raw"
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-PREROUTING" ipVersion=0x4 table="raw"
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-OUTPUT" ipVersion=0x4 table="raw"
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-FORWARD" ipVersion=0x4 table="filter"
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-INPUT" ipVersion=0x4 table="filter"
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-wl-to-host" ipVersion=0x4 table="filter"
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-failsafe-in" ipVersion=0x4 table="filter"
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-OUTPUT" ipVersion=0x4 table="filter"
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-failsafe-out" ipVersion=0x4 table="filter"
2019-11-12 15:47:44.794 [INFO][19004] int_dataplane.go 687: IPIP disabled. Not starting tunnel update thread.
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-PREROUTING" ipVersion=0x4 table="nat"
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-POSTROUTING" ipVersion=0x4 table="nat"
2019-11-12 15:47:44.794 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-OUTPUT" ipVersion=0x4 table="nat"
2019-11-12 15:47:44.795 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-failsafe-in" ipVersion=0x4 table="mangle"
2019-11-12 15:47:44.795 [INFO][19004] table.go 475: Queueing update of chain. chainName="cali-PREROUTING" ipVersion=0x4 table="mangle"
2019-11-12 15:47:44.795 [INFO][19004] daemon.go 300: Connect to the dataplane driver.
2019-11-12 15:47:44.795 [INFO][19004] daemon.go 350: Connecting to Typha. addr="100.71.169.3:5473"
2019-11-12 15:47:44.795 [INFO][19004] sync_client.go 70:  requiringTLS=false
2019-11-12 15:47:44.795 [INFO][19004] daemon.go 372: Created Syncer syncer=<nil>
2019-11-12 15:47:44.795 [INFO][19004] calc_graph.go 110: Creating calculation graph, filtered to hostname local-az-worker-suse-84f78947bf-hlsbt
2019-11-12 15:47:44.795 [INFO][19004] dispatcher.go 68: Registering listener for type model.WorkloadEndpointKey: (dispatcher.UpdateHandler)(0x132e4a0)
2019-11-12 15:47:44.795 [INFO][19004] dispatcher.go 68: Registering listener for type model.HostEndpointKey: (dispatcher.UpdateHandler)(0x132e4a0)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.WorkloadEndpointKey: (dispatcher.UpdateHandler)(0x132e580)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.HostEndpointKey: (dispatcher.UpdateHandler)(0x132e580)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.WorkloadEndpointKey: (dispatcher.UpdateHandler)(0x132e370)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.HostEndpointKey: (dispatcher.UpdateHandler)(0x132e370)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.PolicyKey: (dispatcher.UpdateHandler)(0x132e370)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.ProfileRulesKey: (dispatcher.UpdateHandler)(0x132e370)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.ProfileLabelsKey: (dispatcher.UpdateHandler)(0x132e370)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.ProfileTagsKey: (dispatcher.UpdateHandler)(0x132e370)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.ProfileTagsKey: (dispatcher.UpdateHandler)(0x1289640)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.ProfileLabelsKey: (dispatcher.UpdateHandler)(0x1289640)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.WorkloadEndpointKey: (dispatcher.UpdateHandler)(0x1289640)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.HostEndpointKey: (dispatcher.UpdateHandler)(0x1289640)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.NetworkSetKey: (dispatcher.UpdateHandler)(0x1289640)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.PolicyKey: (dispatcher.UpdateHandler)(0x132e7d0)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.WorkloadEndpointKey: (dispatcher.UpdateHandler)(0x132e7d0)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.HostEndpointKey: (dispatcher.UpdateHandler)(0x132e7d0)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.HostIPKey: (dispatcher.UpdateHandler)(0x132e6f0)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.IPPoolKey: (dispatcher.UpdateHandler)(0x132e6f0)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.GlobalConfigKey: (dispatcher.UpdateHandler)(0x132e610)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.HostConfigKey: (dispatcher.UpdateHandler)(0x132e610)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.ReadyFlagKey: (dispatcher.UpdateHandler)(0x132e610)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.ProfileLabelsKey: (dispatcher.UpdateHandler)(0x132e920)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.HostIPKey: (dispatcher.UpdateHandler)(0x132e9b0)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.WorkloadEndpointKey: (dispatcher.UpdateHandler)(0x132e9b0)
2019-11-12 15:47:44.796 [INFO][19004] dispatcher.go 68: Registering listener for type model.HostEndpointKey: (dispatcher.UpdateHandler)(0x132e9b0)
2019-11-12 15:47:44.797 [INFO][19004] dispatcher.go 68: Registering listener for type model.HostConfigKey: (dispatcher.UpdateHandler)(0x132e9b0)
2019-11-12 15:47:44.797 [INFO][19004] daemon.go 443: Starting the Typha connection
2019-11-12 15:47:44.797 [INFO][19004] sync_client.go 169: Starting Typha client
2019-11-12 15:47:44.797 [INFO][19004] sync_client.go 70:  requiringTLS=false
2019-11-12 15:47:44.797 [INFO][19004] sync_client.go 218: Connecting to Typha. address="100.71.169.3:5473" connID=0x0 type=""
2019-11-12 15:47:44.798 [INFO][19004] int_dataplane.go 774: Started internal iptables dataplane driver loop
2019-11-12 15:47:44.798 [INFO][19004] int_dataplane.go 784: Will refresh IP sets on timer interval=1m30s
2019-11-12 15:47:44.798 [INFO][19004] int_dataplane.go 794: Will refresh routes on timer interval=1m30s
2019-11-12 15:47:44.798 [INFO][19004] int_dataplane.go 1219: Started internal status report thread
2019-11-12 15:47:44.798 [INFO][19004] int_dataplane.go 1221: Process status reports disabled
2019-11-12 15:47:44.798 [INFO][19004] iface_monitor.go 89: Interface monitoring thread started.
2019-11-12 15:47:44.798 [INFO][19004] iface_monitor.go 96: Subscribed to netlink updates.
2019-11-12 15:47:44.801 [INFO][19004] int_dataplane.go 589: Linux interface state changed. ifaceName="lo" state="up"
2019-11-12 15:47:44.801 [INFO][19004] int_dataplane.go 622: Linux interface addrs changed. addrs=set.mapSet{"127.0.0.1":set.empty{}, "::1":set.empty{}} ifaceName="lo"
2019-11-12 15:47:44.801 [INFO][19004] int_dataplane.go 589: Linux interface state changed. ifaceName="eth0" state="up"
2019-11-12 15:47:44.801 [INFO][19004] int_dataplane.go 622: Linux interface addrs changed. addrs=set.mapSet{"10.250.0.4":set.empty{}, "fe80::20d:3aff:fea9:8a6b":set.empty{}} ifaceName="eth0"
2019-11-12 15:47:44.801 [INFO][19004] int_dataplane.go 622: Linux interface addrs changed. addrs=set.mapSet{"172.17.0.1":set.empty{}, "fe80::42:1eff:fee2:e90d":set.empty{}} ifaceName="docker0"
2019-11-12 15:47:44.801 [INFO][19004] int_dataplane.go 589: Linux interface state changed. ifaceName="cali94829a5722f" state="up"
2019-11-12 15:47:44.801 [INFO][19004] sync_client.go 233: Connected to Typha. address="100.71.169.3:5473" connID=0x0 type=""
2019-11-12 15:47:44.802 [INFO][19004] async_calc_graph.go 229: Starting AsyncCalcGraph
2019-11-12 15:47:44.802 [INFO][19004] daemon.go 472: Started the processing graph
2019-11-12 15:47:44.802 [INFO][19004] daemon.go 832: Reading from dataplane driver pipe...
2019-11-12 15:47:44.802 [INFO][19004] sync_client.go 268: Started Typha client main loop address="100.71.169.3:5473" connID=0x0 type=""
2019-11-12 15:47:44.802 [INFO][19004] async_calc_graph.go 134: AsyncCalcGraph running
2019-11-12 15:47:44.802 [INFO][19004] int_dataplane.go 622: Linux interface addrs changed. addrs=set.mapSet{"fe80::ecee:eeff:feee:eeee":set.empty{}} ifaceName="cali94829a5722f"
2019-11-12 15:47:44.803 [INFO][19004] int_dataplane.go 835: Received interface update msg=&intdataplane.ifaceUpdate{Name:"lo", State:"up"}
2019-11-12 15:47:44.803 [INFO][19004] int_dataplane.go 835: Received interface update msg=&intdataplane.ifaceUpdate{Name:"eth0", State:"up"}
2019-11-12 15:47:44.803 [INFO][19004] int_dataplane.go 835: Received interface update msg=&intdataplane.ifaceUpdate{Name:"cali94829a5722f", State:"up"}
2019-11-12 15:47:44.803 [INFO][19004] daemon.go 565: No driver process to monitor
2019-11-12 15:47:44.803 [INFO][19004] int_dataplane.go 850: Received interface addresses update msg=&intdataplane.ifaceAddrsUpdate{Name:"lo", Addrs:set.mapSet{"127.0.0.1":set.empty{}, "::1":set.empty{}}}
2019-11-12 15:47:44.803 [INFO][19004] hostip_mgr.go 84: Interface addrs changed. update=&intdataplane.ifaceAddrsUpdate{Name:"lo", Addrs:set.mapSet{"::1":set.empty{}, "127.0.0.1":set.empty{}}}
2019-11-12 15:47:44.803 [INFO][19004] ipsets.go 119: Queueing IP set for creation family="inet" setID="this-host" setType="hash:ip"
2019-11-12 15:47:44.804 [INFO][19004] int_dataplane.go 850: Received interface addresses update msg=&intdataplane.ifaceAddrsUpdate{Name:"eth0", Addrs:set.mapSet{"10.250.0.4":set.empty{}, "fe80::20d:3aff:fea9:8a6b":set.empty{}}}
2019-11-12 15:47:44.804 [INFO][19004] hostip_mgr.go 84: Interface addrs changed. update=&intdataplane.ifaceAddrsUpdate{Name:"eth0", Addrs:set.mapSet{"10.250.0.4":set.empty{}, "fe80::20d:3aff:fea9:8a6b":set.empty{}}}
2019-11-12 15:47:44.804 [INFO][19004] ipsets.go 119: Queueing IP set for creation family="inet" setID="this-host" setType="hash:ip"
2019-11-12 15:47:44.804 [INFO][19004] sync_client.go 325: Server hello message received address="100.71.169.3:5473" connID=0x0 serverVersion="v3.8.2" type=""
2019-11-12 15:47:44.804 [INFO][19004] int_dataplane.go 850: Received interface addresses update msg=&intdataplane.ifaceAddrsUpdate{Name:"docker0", Addrs:set.mapSet{"172.17.0.1":set.empty{}, "fe80::42:1eff:fee2:e90d":set.empty{}}}
2019-11-12 15:47:44.804 [INFO][19004] hostip_mgr.go 84: Interface addrs changed. update=&intdataplane.ifaceAddrsUpdate{Name:"docker0", Addrs:set.mapSet{"172.17.0.1":set.empty{}, "fe80::42:1eff:fee2:e90d":set.empty{}}}
2019-11-12 15:47:44.804 [INFO][19004] ipsets.go 119: Queueing IP set for creation family="inet" setID="this-host" setType="hash:ip"
2019-11-12 15:47:44.805 [INFO][19004] int_dataplane.go 850: Received interface addresses update msg=&intdataplane.ifaceAddrsUpdate{Name:"cali94829a5722f", Addrs:set.mapSet{"fe80::ecee:eeff:feee:eeee":set.empty{}}}
2019-11-12 15:47:44.805 [INFO][19004] hostip_mgr.go 84: Interface addrs changed. update=&intdataplane.ifaceAddrsUpdate{Name:"cali94829a5722f", Addrs:set.mapSet{"fe80::ecee:eeff:feee:eeee":set.empty{}}}
2019-11-12 15:47:44.805 [INFO][19004] int_dataplane.go 820: Received *proto.ConfigUpdate update from calculation graph msg=config:<key:"CalicoVersion" value:"v3.8.2" > config:<key:"ClusterGUID" value:"5075b44df893404da853f337a40d18a1" > config:<key:"ClusterType" value:"k8s,bgp,kdd,typha" > config:<key:"DatastoreType" value:"kubernetes" > config:<key:"DefaultEndpointToHostAction" value:"ACCEPT" > config:<key:"FelixHostname" value:"local-az-worker-suse-84f78947bf-hlsbt" > config:<key:"HealthEnabled" value:"true" > config:<key:"IpInIpEnabled" value:"false" > config:<key:"IpInIpMtu" value:"1440" > config:<key:"IpInIpTunnelAddr" value:"100.96.1.1" > config:<key:"Ipv6Support" value:"false" > config:<key:"LogFilePath" value:"None" > config:<key:"LogSeverityFile" value:"None" > config:<key:"LogSeverityScreen" value:"info" > config:<key:"LogSeveritySys" value:"None" > config:<key:"MetadataAddr" value:"None" > config:<key:"NATPortRange" value:"32768:65535" > config:<key:"ReportingIntervalSecs" value:"0" > config:<key:"TyphaK8sServiceName" value:"calico-typha" >
2019-11-12 15:47:46.895 [INFO][19004] health.go 178: Overall health status changed lastSummary=&health.HealthReport{Live:true, Ready:false}
2019-11-12 15:47:46.895 [WARNING][19004] health.go 190: Reporter failed readiness checks name="int_dataplane" reporter-state=&health.reporterState{name:"int_dataplane", reports:health.HealthReport{Live:true, Ready:true}, timeout:20000000000, latest:health.HealthReport{Live:true, Ready:false}, timestamp:time.Time{wall:0xbf6ad2e82f9a7e30, ext:272513101, loc:(*time.Location)(0x2b314c0)}}
2019-11-12 15:47:46.895 [WARNING][19004] health.go 190: Reporter failed readiness checks name="async_calc_graph" reporter-state=&health.reporterState{name:"async_calc_graph", reports:health.HealthReport{Live:true, Ready:true}, timeout:20000000000, latest:health.HealthReport{Live:true, Ready:false}, timestamp:time.Time{wall:0xbf6ad2e82fdc2f60, ext:276818301, loc:(*time.Location)(0x2b314c0)}}
2019-11-12 15:48:14.804 [ERROR][19004] sync_client.go 260: Failed to read from server address="100.71.169.3:5473" connID=0x0 error=read tcp 10.250.0.4:46700->100.71.169.3:5473: i/o timeout type=""
2019-11-12 15:48:14.805 [INFO][19004] sync_client.go 155: Typha client Context asked us to exit connID=0x0 type=""
2019-11-12 15:48:14.806 [WARNING][19004] daemon.go 592: Felix is shutting down reason="Connection to Typha failed"
2019-11-12 15:48:14.806 [INFO][19004] daemon.go 632: Sleeping to avoid tight restart loop. reason="Connection to Typha failed"
2019-11-12 15:48:16.806 [FATAL][19004] daemon.go 641: Exiting. reason="Connection to Typha failed"

calicoctl-node-status from the container running calico

$ calicoctl node status
Calico process is running.

None of the BGP backend processes (BIRD or GoBGP) are running.

calicoctl-node-status from the node hosting calico-node container

$ calicoctl node status
Calico process is running.

None of the BGP backend processes (BIRD or GoBGP) are running.

calicoctl-get-node from the container running calico

$ calicoctl get node
NAME
local-az-worker-suse-84f78947bf-7hwh9
local-az-worker-suse-84f78947bf-hlsbt

calicoctl-node-checksystem from the container running calico

$ calicoctl node checksystem                                                                               
Checking kernel version...
                4.12.14-197.21-default                                  OK
Checking kernel modules...
                xt_set                                                  OK
                ip6_tables                                              OK
System meets minimum system requirements to run Calico!

calicoctl-node-diags from the container running calico

diag.tar.gz

vpnachev picture vpnachev on 12 Nov 2019

In both your original post and the latest, calico-node logs in the connection error show something like 10.250.0.4:46700->100.71.169.3:5473. Seems like calico-node is coming from the node internal address but for some reason the address calico-node is getting for typha is at (I'm assuming) an external address.

tmjd picture tmjd on 22 Nov 2019

@tmjd thanks for looking into the logs. 10.250.0.4 is the internal IP of the node, as you see, and 100.71.169.3 is the IP of the ClusterIP Service exposing calico-typha.

vpnachev picture vpnachev on 22 Nov 2019

@fasaxc why is node trying to connect to the service IP of typha? It should be fetching the endpoints and connecting directly.

tmjd picture tmjd on 25 Nov 2019

That's what I thought but now I check the code it's not what we do. We _do_ connect to the cluster IP and let kube-proxy do the load balancing. D'oh!

fasaxc picture fasaxc on 26 Nov 2019
👍1

I don't understand how access from a host (with node on it) to typha can work but access from the node on the same host to typha would fail. The Node pod is ran as hostNetwork so it uses the same network namespace as the host, both are using the service IP, there is no DNS involved.
I think you'll need to try access from both and collect traffic with tcpdump and see where the difference is (where the traffic is being blocked/failing/dropped).

tmjd picture tmjd on 27 Nov 2019

@marwinski and @zanetworker joined into debugging this issue.
It turns out that SUSE by default uses MTU of 9000 which is too high, thus the communication between calico nodes and typha is not reliable(lost packets).

I would like thanks to everybody who took part into this issue.

vpnachev picture vpnachev on 16 Dec 2019
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

caseydavenport picture caseydavenport  路  3Comments
jpiper picture jpiper  路  4Comments
mohit5577 picture mohit5577  路  5Comments
squat picture squat  路  5Comments
winromulus picture winromulus  路  3Comments