k3s-io / k3s

Lightweight Kubernetes
https://k3s.io
Apache License 2.0
28.04k stars 2.35k forks source link

Network policy enforcement is delayed #947

Closed wilsonianb closed 3 years ago

wilsonianb commented 5 years ago

Version: k3s version v0.10.0 (f9888ca3)

Describe the bug There appears to be period of time (<1 minute) after a pod is started during which applicable network policies are not enforced.

To Reproduce Steps to reproduce the behavior: https://github.com/ahmetb/kubernetes-network-policy-recipes/blob/master/11-deny-egress-traffic-from-an-application.md

Expected behavior All egress requests (via wget) from the app=foo labeled pod should fail with either bad address or download timed out (depending on the network policy in use).

Actual behavior Egress requests (via wget) from the app=foo labeled pod initially succeed after pod startup before eventually failing as expected.

Additional context

consideRatio commented 4 years ago

@williamsandrew thanks for reporting this! I ran into this as well. I figure it would be useful to be able to reproduce this for anyone that knows enough to try resolve this, and here is how.

My environment

Ubuntu 20.04, k3s v1.17.4+k3s1 (3eee8ac3) with --docker, and docker version 19.03.8.

Reproduction script

Toggle me ```shell echo "Installing k3s..." curl -sfL https://get.k3s.io | sh -s - \ --write-kubeconfig-mode=644 \ --disable metrics-server \ --disable traefik \ --disable local-storage \ --docker echo "Installing a networkpolicy, service, and deployment for an echoserver ..." cat << EOF | k3s kubectl apply -f - apiVersion: networking.k8s.io/v1 kind: NetworkPolicy metadata: name: echoserver spec: podSelector: matchLabels: app: echoserver policyTypes: - Ingress ingress: - from: - podSelector: matchLabels: echoserver-access: "true" --- apiVersion: v1 kind: Service metadata: name: echoserver spec: ports: - port: 80 targetPort: 8080 selector: app: echoserver --- apiVersion: apps/v1 kind: Deployment metadata: name: echoserver spec: selector: matchLabels: app: echoserver template: metadata: labels: app: echoserver spec: containers: - name: echoserver image: gcr.io/google_containers/echoserver:1.10 ports: - containerPort: 8080 EOF echo "waiting for the deployed echoserver to be ready ..." k3s kubectl rollout status --watch deploy/echoserver echo "Trying to access echoserver without the correct label for access..." k3s kubectl run -it --rm --restart=Never --image=busybox --generator=run-pod/v1 busybox-without-access -- sh -c 'while ! wget -q -O- http://$ECHOSERVER_SERVICE_HOST; do sleep 5; done' echo "Waiting two minutes to see if something changes..." sleep 120 echo "Trying to access echoserver with the correct label for access..." k3s kubectl run -it --rm --restart=Never --image=busybox --generator=run-pod/v1 --labels=echoserver-access=true busybox-with-access -- sh -c 'while ! wget -q -O- http://$ECHOSERVER_SERVICE_HOST; do sleep 5; done' ```

Observation

The busybox-without-access had access, and then after waitin for two minutes, the busybox-with-access failed to get access during the initial ~40 seconds, and then got access.

I see two issues which may relate:

  1. Briefly after k3s cluster creation (<3 min), the network policy controller doesn't seem to be active, and allows access to a pod targeted by a network policy and should not be allowed to be accessed.
  2. With a fully started k3s cluster, but in a recently started container with access to another pod thanks to a k8s label allowing it, the network policy controller denies access for ~40 seconds and then finally allows it.

Diagnostics

Output of: journalctl -u k3s --since "10 minutes ago" ``` systemd[1]: Starting Lightweight Kubernetes... time="2020-05-13T01:39:52+02:00" level=info msg="Preparing data dir /var/lib/rancher/k3s/data/6a3098e6644f5f0dbfe14e5efa99bb8fdf60d63cae89fdffd71b7de11a1f1430" time="2020-05-13T01:39:54.215854885+02:00" level=info msg="Starting k3s v1.17.4+k3s1 (3eee8ac3)" time="2020-05-13T01:39:54.230242171+02:00" level=info msg="Kine listening on unix://kine.sock" time="2020-05-13T01:39:54.392381913+02:00" level=info msg="Active TLS secret (ver=) (count 7): map[listener.cattle.io/cn-10.43.0.1:10.43.0.1 listener.cattle.io/cn-127.0.0.1:127.0.0.1 listener.cattle.io/cn-192.168.43.141:192.168.43.141 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kub> time="2020-05-13T01:39:54.399652948+02:00" level=info msg="Running kube-apiserver --advertise-port=6443 --allow-privileged=true --anonymous-auth=false --api-audiences=unknown --authorization-mode=Node,RBAC --basic-auth-file=/var/lib/rancher/k3s/server/cred/passwd --bind-address=127.0.0.1 --cert-dir=/var/lib/rancher/k3s/ser> Flag --basic-auth-file has been deprecated, Basic authentication mode is deprecated and will be removed in a future release. It is not recommended for production environments. I0513 01:39:54.400377 server.go:622] external host was not specified, using 192.168.43.141 I0513 01:39:54.400607 server.go:163] Version: v1.17.4+k3s1 I0513 01:39:54.841976 plugins.go:158] Loaded 11 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,MutatingAdmissionWebhook,Runtim> I0513 01:39:54.841993 plugins.go:161] Loaded 7 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,Priority,PersistentVolumeClaimResize,ValidatingAdmissionWebhook,RuntimeClass,ResourceQuota. I0513 01:39:54.842977 plugins.go:158] Loaded 11 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,MutatingAdmissionWebhook,Runtim> I0513 01:39:54.842986 plugins.go:161] Loaded 7 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,Priority,PersistentVolumeClaimResize,ValidatingAdmissionWebhook,RuntimeClass,ResourceQuota. I0513 01:39:54.865676 master.go:267] Using reconciler: lease I0513 01:39:54.920858 rest.go:115] the default service ipfamily for this cluster is: IPv4 W0513 01:39:55.190331 genericapiserver.go:409] Skipping API batch/v2alpha1 because it has no resources. W0513 01:39:55.197876 genericapiserver.go:409] Skipping API discovery.k8s.io/v1alpha1 because it has no resources. W0513 01:39:55.204907 genericapiserver.go:409] Skipping API node.k8s.io/v1alpha1 because it has no resources. W0513 01:39:55.222941 genericapiserver.go:409] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources. W0513 01:39:55.225664 genericapiserver.go:409] Skipping API scheduling.k8s.io/v1alpha1 because it has no resources. W0513 01:39:55.238424 genericapiserver.go:409] Skipping API storage.k8s.io/v1alpha1 because it has no resources. W0513 01:39:55.253586 genericapiserver.go:409] Skipping API apps/v1beta2 because it has no resources. W0513 01:39:55.253606 genericapiserver.go:409] Skipping API apps/v1beta1 because it has no resources. I0513 01:39:55.260738 plugins.go:158] Loaded 11 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,MutatingAdmissionWebhook,Runtim> I0513 01:39:55.260752 plugins.go:161] Loaded 7 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,Priority,PersistentVolumeClaimResize,ValidatingAdmissionWebhook,RuntimeClass,ResourceQuota. I0513 01:39:56.632483 dynamic_cafile_content.go:166] Starting request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt I0513 01:39:56.632483 dynamic_cafile_content.go:166] Starting client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt I0513 01:39:56.632676 dynamic_serving_content.go:129] Starting serving-cert::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key I0513 01:39:56.633165 secure_serving.go:178] Serving securely on 127.0.0.1:6444 I0513 01:39:56.633240 tlsconfig.go:219] Starting DynamicServingCertificateController I0513 01:39:56.633290 autoregister_controller.go:140] Starting autoregister controller I0513 01:39:56.633301 cache.go:32] Waiting for caches to sync for autoregister controller I0513 01:39:56.633361 available_controller.go:386] Starting AvailableConditionController I0513 01:39:56.633362 crdregistration_controller.go:111] Starting crd-autoregister controller I0513 01:39:56.633372 cache.go:32] Waiting for caches to sync for AvailableConditionController controller I0513 01:39:56.633378 shared_informer.go:197] Waiting for caches to sync for crd-autoregister I0513 01:39:56.633407 apiservice_controller.go:94] Starting APIServiceRegistrationController I0513 01:39:56.633413 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller I0513 01:39:56.633411 crd_finalizer.go:263] Starting CRDFinalizer I0513 01:39:56.633428 establishing_controller.go:73] Starting EstablishingController I0513 01:39:56.633416 controller.go:85] Starting OpenAPI controller I0513 01:39:56.633460 apiapproval_controller.go:185] Starting KubernetesAPIApprovalPolicyConformantConditionController I0513 01:39:56.633471 customresource_discovery_controller.go:208] Starting DiscoveryController I0513 01:39:56.633493 nonstructuralschema_controller.go:191] Starting NonStructuralSchemaConditionController I0513 01:39:56.633504 naming_controller.go:288] Starting NamingConditionController I0513 01:39:56.633971 cluster_authentication_trust_controller.go:440] Starting cluster_authentication_trust_controller controller I0513 01:39:56.633985 shared_informer.go:197] Waiting for caches to sync for cluster_authentication_trust_controller I0513 01:39:56.634019 controller.go:81] Starting OpenAPI AggregationController I0513 01:39:56.634031 dynamic_cafile_content.go:166] Starting client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt I0513 01:39:56.634068 dynamic_cafile_content.go:166] Starting request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt E0513 01:39:56.650251 controller.go:150] Unable to perform initial Kubernetes service initialization: Service "kubernetes" is invalid: spec.clusterIP: Invalid value: "10.43.0.1": cannot allocate resources of type serviceipallocations at this time E0513 01:39:56.650877 controller.go:155] Unable to remove old endpoints from kubernetes service: StorageError: key not found, Code: 1, Key: /registry/masterleases/192.168.43.141, ResourceVersion: 0, AdditionalErrorMsg: I0513 01:39:56.733781 cache.go:39] Caches are synced for APIServiceRegistrationController controller I0513 01:39:56.733808 shared_informer.go:204] Caches are synced for crd-autoregister I0513 01:39:56.733810 cache.go:39] Caches are synced for autoregister controller I0513 01:39:56.733830 cache.go:39] Caches are synced for AvailableConditionController controller I0513 01:39:56.734121 shared_informer.go:204] Caches are synced for cluster_authentication_trust_controller I0513 01:39:57.633020 controller.go:107] OpenAPI AggregationController: Processing item I0513 01:39:57.633097 controller.go:130] OpenAPI AggregationController: action for item : Nothing (removed from the queue). I0513 01:39:57.633127 controller.go:130] OpenAPI AggregationController: action for item k8s_internal_local_delegation_chain_0000000000: Nothing (removed from the queue). I0513 01:39:57.641006 storage_scheduling.go:133] created PriorityClass system-node-critical with value 2000001000 I0513 01:39:57.643317 storage_scheduling.go:133] created PriorityClass system-cluster-critical with value 2000000000 I0513 01:39:57.643331 storage_scheduling.go:142] all system priority classes are created successfully or already exist. I0513 01:39:57.843806 controller.go:606] quota admission added evaluator for: roles.rbac.authorization.k8s.io I0513 01:39:57.875028 controller.go:606] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io W0513 01:39:57.976613 lease.go:224] Resetting endpoints for master service "kubernetes" to [192.168.43.141] I0513 01:39:57.977062 controller.go:606] quota admission added evaluator for: endpoints time="2020-05-13T01:39:58.645992150+02:00" level=info msg="Running kube-scheduler --bind-address=127.0.0.1 --kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --leader-elect=false --port=10251 --secure-port=0" time="2020-05-13T01:39:58.647520389+02:00" level=info msg="Running kube-controller-manager --allocate-node-cidrs=true --bind-address=127.0.0.1 --cluster-cidr=10.42.0.0/16 --cluster-signing-cert-file=/var/lib/rancher/k3s/server/tls/server-ca.crt --cluster-signing-key-file=/var/lib/rancher/k3s/server/tls/server-ca.key --kube> I0513 01:39:58.652052 controllermanager.go:161] Version: v1.17.4+k3s1 I0513 01:39:58.652544 deprecated_insecure_serving.go:53] Serving insecurely on [::]:10252 time="2020-05-13T01:39:58.652817554+02:00" level=info msg="Waiting for cloudcontroller rbac role to be created" time="2020-05-13T01:39:58.653730271+02:00" level=info msg="Creating CRD addons.k3s.cattle.io" W0513 01:39:58.655985 authorization.go:47] Authorization is disabled W0513 01:39:58.655998 authentication.go:92] Authentication is disabled I0513 01:39:58.656005 deprecated_insecure_serving.go:51] Serving healthz insecurely on [::]:10251 time="2020-05-13T01:39:58.657809189+02:00" level=info msg="Creating CRD helmcharts.helm.cattle.io" time="2020-05-13T01:39:58.664989295+02:00" level=info msg="Waiting for CRD helmcharts.helm.cattle.io to become available" I0513 01:39:58.965824 plugins.go:100] No cloud provider specified. I0513 01:39:58.968711 shared_informer.go:197] Waiting for caches to sync for tokens I0513 01:39:58.972981 controller.go:606] quota admission added evaluator for: serviceaccounts I0513 01:39:58.974930 controllermanager.go:533] Started "statefulset" W0513 01:39:58.974942 controllermanager.go:512] "bootstrapsigner" is disabled I0513 01:39:58.975013 stateful_set.go:145] Starting stateful set controller I0513 01:39:58.975022 shared_informer.go:197] Waiting for caches to sync for stateful set I0513 01:39:58.979960 controllermanager.go:533] Started "pv-protection" I0513 01:39:58.980060 pv_protection_controller.go:81] Starting PV protection controller I0513 01:39:58.980090 shared_informer.go:197] Waiting for caches to sync for PV protection I0513 01:39:58.985581 controllermanager.go:533] Started "endpoint" I0513 01:39:58.985673 endpoints_controller.go:181] Starting endpoint controller I0513 01:39:58.985685 shared_informer.go:197] Waiting for caches to sync for endpoint I0513 01:39:58.991013 controllermanager.go:533] Started "podgc" I0513 01:39:58.991081 gc_controller.go:88] Starting GC controller I0513 01:39:58.991091 shared_informer.go:197] Waiting for caches to sync for GC I0513 01:39:58.996368 node_lifecycle_controller.go:77] Sending events to api server E0513 01:39:58.996393 core.go:232] failed to start cloud node lifecycle controller: no cloud provider provided W0513 01:39:58.996400 controllermanager.go:525] Skipping "cloud-node-lifecycle" I0513 01:39:59.001773 controllermanager.go:533] Started "attachdetach" I0513 01:39:59.001793 attach_detach_controller.go:342] Starting attach detach controller I0513 01:39:59.001804 shared_informer.go:197] Waiting for caches to sync for attach detach I0513 01:39:59.007929 controllermanager.go:533] Started "job" I0513 01:39:59.008013 job_controller.go:143] Starting job controller I0513 01:39:59.008020 shared_informer.go:197] Waiting for caches to sync for job I0513 01:39:59.013491 controllermanager.go:533] Started "csrapproving" I0513 01:39:59.013596 certificate_controller.go:118] Starting certificate controller "csrapproving" I0513 01:39:59.013607 shared_informer.go:197] Waiting for caches to sync for certificate-csrapproving I0513 01:39:59.015732 controllermanager.go:533] Started "csrcleaner" I0513 01:39:59.015851 cleaner.go:81] Starting CSR cleaner controller I0513 01:39:59.021953 controllermanager.go:533] Started "serviceaccount" I0513 01:39:59.021990 serviceaccounts_controller.go:116] Starting service account controller I0513 01:39:59.021998 shared_informer.go:197] Waiting for caches to sync for service account I0513 01:39:59.024137 node_ipam_controller.go:94] Sending events to api server. I0513 01:39:59.068970 shared_informer.go:204] Caches are synced for tokens time="2020-05-13T01:39:59.171621558+02:00" level=info msg="Done waiting for CRD helmcharts.helm.cattle.io to become available" time="2020-05-13T01:39:59.190588979+02:00" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-1.81.0.tgz" time="2020-05-13T01:39:59.191173593+02:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml" time="2020-05-13T01:39:59.191463038+02:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml" time="2020-05-13T01:39:59.191831355+02:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/coredns.yaml" time="2020-05-13T01:39:59.292649620+02:00" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller" time="2020-05-13T01:39:59.292775669+02:00" level=info msg="Waiting for master node startup: resource name may not be empty" time="2020-05-13T01:39:59.293261046+02:00" level=info msg="Node token is available at /var/lib/rancher/k3s/server/token" time="2020-05-13T01:39:59.293329175+02:00" level=info msg="To join node to cluster: k3s agent -s https://192.168.43.141:6443 -t ${NODE_TOKEN}" I0513 01:39:59.316659 controller.go:606] quota admission added evaluator for: addons.k3s.cattle.io http: TLS handshake error from 127.0.0.1:60374: remote error: tls: bad certificate time="2020-05-13T01:39:59.358535557+02:00" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml" time="2020-05-13T01:39:59.358577536+02:00" level=info msg="Run: k3s kubectl" time="2020-05-13T01:39:59.358585189+02:00" level=info msg="k3s is up and running" time="2020-05-13T01:39:59.358718692+02:00" level=info msg="module overlay was already loaded" time="2020-05-13T01:39:59.358740447+02:00" level=info msg="module nf_conntrack was already loaded" time="2020-05-13T01:39:59.358750641+02:00" level=info msg="module br_netfilter was already loaded" systemd[1]: Started Lightweight Kubernetes. http: TLS handshake error from 127.0.0.1:60382: remote error: tls: bad certificate http: TLS handshake error from 127.0.0.1:60388: remote error: tls: bad certificate I0513 01:39:59.376582 controller.go:606] quota admission added evaluator for: deployments.apps time="2020-05-13T01:39:59.387266283+02:00" level=info msg="Running kubelet --address=0.0.0.0 --anonymous-auth=false --authentication-token-webhook=true --authorization-mode=Webhook --cgroup-driver=cgroupfs --client-ca-file=/var/lib/rancher/k3s/agent/client-ca.crt --cloud-provider=external --cluster-dns=10.43.0.10 --cluster> time="2020-05-13T01:39:59.387331776+02:00" level=info msg="Running kube-proxy --cluster-cidr=10.42.0.0/16 --healthz-bind-address=127.0.0.1 --hostname-override=sos --kubeconfig=/var/lib/rancher/k3s/agent/kubeproxy.kubeconfig --proxy-mode=iptables" W0513 01:39:59.387434 server.go:213] WARNING: all flags other than --config, --write-config-to, and --cleanup are deprecated. Please begin using a config file ASAP. time="2020-05-13T01:39:59.394372645+02:00" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller" time="2020-05-13T01:39:59.394380724+02:00" level=info msg="Starting batch/v1, Kind=Job controller" time="2020-05-13T01:39:59.395038163+02:00" level=info msg="waiting for node sos: nodes \"sos\" not found" time="2020-05-13T01:39:59.399049731+02:00" level=info msg="Starting /v1, Kind=Node controller" time="2020-05-13T01:39:59.399057456+02:00" level=info msg="Starting /v1, Kind=Pod controller" time="2020-05-13T01:39:59.399071412+02:00" level=info msg="Starting /v1, Kind=Service controller" time="2020-05-13T01:39:59.399110686+02:00" level=info msg="Starting /v1, Kind=Endpoints controller" time="2020-05-13T01:39:59.399125793+02:00" level=info msg="Starting /v1, Kind=Secret controller" I0513 01:39:59.401345 server.go:412] Version: v1.17.4+k3s1 E0513 01:39:59.405472 node.go:124] Failed to retrieve node info: nodes "sos" not found I0513 01:39:59.427481 server.go:639] --cgroups-per-qos enabled, but --cgroup-root was not specified. defaulting to / I0513 01:39:59.427938 container_manager_linux.go:271] container manager verified user specified cgroup-root exists: [] I0513 01:39:59.427954 container_manager_linux.go:276] Creating Container Manager object based on Node Config: {RuntimeCgroupsName:/systemd/system.slice SystemCgroupsName: KubeletCgroupsName:/systemd/system.slice ContainerRuntime:docker CgroupsPerQOS:true CgroupRoot:/ CgroupDriver:cgroupfs KubeletRootDir:/var/lib/ku> I0513 01:39:59.428034 fake_topology_manager.go:29] [fake topologymanager] NewFakeManager I0513 01:39:59.428040 container_manager_linux.go:311] Creating device plugin manager: true I0513 01:39:59.428093 fake_topology_manager.go:39] [fake topologymanager] AddHintProvider HintProvider: &{kubelet.sock /var/lib/kubelet/device-plugins/ map[] {0 0} {{} [0 0 0]} 0x2c49910 0x6dd8210 0x2c4a1e0 map[] map[] map[] map[] map[] 0xc007d37230 [0] 0x6dd8210} I0513 01:39:59.428121 state_mem.go:36] [cpumanager] initializing new in-memory state store I0513 01:39:59.429352 fake_topology_manager.go:39] [fake topologymanager] AddHintProvider HintProvider: &{{0 0} 0x6dd8210 10000000000 0xc007c2b020 map[] 0x6dd8210} I0513 01:39:59.429535 kubelet.go:311] Watching apiserver I0513 01:39:59.430238 client.go:75] Connecting to docker on unix:///var/run/docker.sock I0513 01:39:59.430256 client.go:104] Start docker client with request timeout=2m0s W0513 01:39:59.435629 docker_service.go:564] Hairpin mode set to "promiscuous-bridge" but kubenet is not enabled, falling back to "hairpin-veth" I0513 01:39:59.435649 docker_service.go:240] Hairpin mode set to "hairpin-veth" I0513 01:39:59.442162 docker_service.go:255] Docker cri networking managed by cni I0513 01:39:59.448877 docker_service.go:260] Docker Info: &{ID:VWUU:ZW6A:YX3O:TNIL:PHGN:IKDP:ILHT:ZOLE:EOXY:5CAV:KSFC:FBGB Containers:58 ContainersRunning:4 ContainersPaused:0 ContainersStopped:54 Images:122 Driver:overlay2 DriverStatus:[[Backing Filesystem ] [Supports d_type true] [Native Overlay Diff tru> I0513 01:39:59.448979 docker_service.go:274] Setting cgroupDriver to cgroupfs I0513 01:39:59.460276 kuberuntime_manager.go:211] Container runtime docker initialized, version: 19.03.8, apiVersion: 1.40.0 I0513 01:39:59.464991 server.go:1111] Started kubelet I0513 01:39:59.465030 server.go:144] Starting to listen on 0.0.0.0:10250 E0513 01:39:59.465053 kubelet.go:1302] Image garbage collection failed once. Stats initialization may not have completed yet: failed to get imageFs info: unable to find data in memory cache I0513 01:39:59.466255 server.go:384] Adding debug handlers to kubelet server. I0513 01:39:59.466527 fs_resource_analyzer.go:64] Starting FS ResourceAnalyzer I0513 01:39:59.466594 volume_manager.go:265] Starting Kubelet Volume Manager I0513 01:39:59.466783 desired_state_of_world_populator.go:138] Desired state populator starts to run I0513 01:39:59.478228 status_manager.go:157] Starting to sync pod status with apiserver I0513 01:39:59.478261 kubelet.go:1820] Starting kubelet main sync loop. E0513 01:39:59.478298 kubelet.go:1844] skipping pod synchronization - [container runtime status check may not have completed yet, PLEG is not healthy: pleg has yet to be successful] time="2020-05-13T01:39:59.495437790+02:00" level=info msg="Active TLS secret k3s-serving (ver=198) (count 7): map[listener.cattle.io/cn-10.43.0.1:10.43.0.1 listener.cattle.io/cn-127.0.0.1:127.0.0.1 listener.cattle.io/cn-192.168.43.141:192.168.43.141 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernet> E0513 01:39:59.504397 controller.go:227] failed to get node "sos" when trying to set owner ref to the node lease: nodes "sos" not found W0513 01:39:59.511375 docker_sandbox.go:394] failed to read pod IP from plugin/docker: networkPlugin cni failed on the status hook for pod "coredns-6c6bb68b64-cgbtv_kube-system": unexpected command output Device "eth0" does not exist. with error: exit status 1 W0513 01:39:59.525788 docker_sandbox.go:394] failed to read pod IP from plugin/docker: networkPlugin cni failed on the status hook for pod "echoserver-5d8cc8d48-ccf75_default": unexpected command output Device "eth0" does not exist. with error: exit status 1 I0513 01:39:59.566729 kubelet_node_status.go:294] Setting node annotation to enable volume controller attach/detach E0513 01:39:59.566956 kubelet.go:2263] node "sos" not found I0513 01:39:59.573797 kubelet_node_status.go:70] Attempting to register node sos E0513 01:39:59.578387 kubelet.go:1844] skipping pod synchronization - container runtime status check may not have completed yet I0513 01:39:59.590212 kubelet_node_status.go:294] Setting node annotation to enable volume controller attach/detach I0513 01:39:59.596291 cpu_manager.go:173] [cpumanager] starting with none policy I0513 01:39:59.596304 cpu_manager.go:174] [cpumanager] reconciling every 10s I0513 01:39:59.596311 policy_none.go:43] [cpumanager] none policy: Start W0513 01:39:59.597333 manager.go:577] Failed to retrieve checkpoint for "kubelet_internal_checkpoint": checkpoint is not found I0513 01:39:59.597566 plugin_manager.go:114] Starting Kubelet Plugin Manager E0513 01:39:59.597575 eviction_manager.go:246] eviction manager: failed to get summary stats: failed to get node info: node "sos" not found time="2020-05-13T01:39:59.656202918+02:00" level=info msg="Running cloud-controller-manager --allocate-node-cidrs=true --allow-untagged-cloud=true --bind-address=127.0.0.1 --cloud-provider=k3s --cluster-cidr=10.42.0.0/16 --kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --leader-elect=false --node-s> Flag --allow-untagged-cloud has been deprecated, This flag is deprecated and will be removed in a future release. A cluster-id will be required on cloud instances. I0513 01:39:59.659223 controllermanager.go:120] Version: v1.17.4+k3s1 W0513 01:39:59.659237 controllermanager.go:132] detected a cluster without a ClusterID. A ClusterID will be required in the future. Please tag your cluster to avoid any future issues I0513 01:39:59.661095 node_controller.go:110] Sending events to api server. I0513 01:39:59.661134 controllermanager.go:247] Started "cloud-node" I0513 01:39:59.662323 node_lifecycle_controller.go:77] Sending events to api server I0513 01:39:59.662395 controllermanager.go:247] Started "cloud-node-lifecycle" E0513 01:39:59.663599 core.go:90] Failed to start service controller: the cloud provider does not support external load balancers W0513 01:39:59.663611 controllermanager.go:244] Skipping "service" W0513 01:39:59.663619 core.go:108] configure-cloud-routes is set, but cloud provider does not support routes. Will not configure cloud provider routes. W0513 01:39:59.663623 controllermanager.go:244] Skipping "route" E0513 01:39:59.667049 kubelet.go:2263] node "sos" not found E0513 01:39:59.767140 kubelet.go:2263] node "sos" not found I0513 01:39:59.832436 kubelet_node_status.go:73] Successfully registered node sos time="2020-05-13T01:39:59.835394055+02:00" level=info msg="couldn't find node internal ip label on node sos" time="2020-05-13T01:39:59.835417907+02:00" level=info msg="couldn't find node hostname label on node sos" time="2020-05-13T01:39:59.842827707+02:00" level=info msg="Updated coredns node hosts entry [192.168.43.141 sos]" time="2020-05-13T01:39:59.843301955+02:00" level=info msg="couldn't find node internal ip label on node sos" time="2020-05-13T01:39:59.843324064+02:00" level=info msg="couldn't find node hostname label on node sos" I0513 01:39:59.843342 node_controller.go:424] Successfully initialized node sos with cloud provider I0513 01:39:59.867272 reconciler.go:156] Reconciler: start to sync state I0513 01:40:00.446786 node.go:135] Successfully retrieved node IP: 192.168.43.141 I0513 01:40:00.446814 server_others.go:146] Using iptables Proxier. I0513 01:40:00.447261 server.go:571] Version: v1.17.4+k3s1 I0513 01:40:00.447704 conntrack.go:52] Setting nf_conntrack_max to 393216 I0513 01:40:00.447980 config.go:131] Starting endpoints config controller I0513 01:40:00.447994 config.go:313] Starting service config controller I0513 01:40:00.447997 shared_informer.go:197] Waiting for caches to sync for endpoints config I0513 01:40:00.448004 shared_informer.go:197] Waiting for caches to sync for service config I0513 01:40:00.548332 shared_informer.go:204] Caches are synced for service config I0513 01:40:00.548332 shared_informer.go:204] Caches are synced for endpoints config time="2020-05-13T01:40:00.699452943+02:00" level=info msg="master role label has been set succesfully on node: sos" time="2020-05-13T01:40:01.401081559+02:00" level=info msg="waiting for node sos CIDR not assigned yet" W0513 01:40:01.490200 kubelet_getters.go:297] Path "/var/lib/kubelet/pods/aff89412-28be-469e-bf33-1b31ce548c12/volumes" does not exist W0513 01:40:01.490229 kubelet_getters.go:297] Path "/var/lib/kubelet/pods/779b1ac6-e32a-4ebe-8fe6-5647cccdee8c/volumes" does not exist W0513 01:40:01.625925 cni.go:331] CNI failed to retrieve network namespace path: cannot find network namespace for the terminated container "5fbea2ef70569cf8c94c09c598baea2446decb9fd732e1eacadeb6ad60cd4aad" W0513 01:40:01.670556 cni.go:331] CNI failed to retrieve network namespace path: cannot find network namespace for the terminated container "9e11cd8b2ef0fd98380bb3df5032b4b0105892a4088d2e610bf89798473a5c06" W0513 01:40:02.545513 pod_container_deletor.go:75] Container "9e11cd8b2ef0fd98380bb3df5032b4b0105892a4088d2e610bf89798473a5c06" not found in pod's containers W0513 01:40:02.552405 pod_container_deletor.go:75] Container "5fbea2ef70569cf8c94c09c598baea2446decb9fd732e1eacadeb6ad60cd4aad" not found in pod's containers time="2020-05-13T01:40:03.406392590+02:00" level=info msg="waiting for node sos CIDR not assigned yet" time="2020-05-13T01:40:04.390709377+02:00" level=info msg="Tunnel endpoint watch event: [192.168.43.141:6443]" time="2020-05-13T01:40:04.390813405+02:00" level=info msg="Connecting to proxy" url="wss://192.168.43.141:6443/v1-k3s/connect" time="2020-05-13T01:40:04.393572091+02:00" level=info msg="Handling backend connection request [sos]" time="2020-05-13T01:40:05.412344174+02:00" level=info msg="waiting for node sos CIDR not assigned yet" I0513 01:40:06.510686 controller.go:606] quota admission added evaluator for: networkpolicies.networking.k8s.io time="2020-05-13T01:40:07.419645008+02:00" level=info msg="waiting for node sos CIDR not assigned yet" I0513 01:40:09.035810 range_allocator.go:82] Sending events to api server. I0513 01:40:09.035936 range_allocator.go:110] No Service CIDR provided. Skipping filtering out service addresses. I0513 01:40:09.035944 range_allocator.go:116] No Secondary Service CIDR provided. Skipping filtering out secondary service addresses. I0513 01:40:09.035964 controllermanager.go:533] Started "nodeipam" I0513 01:40:09.036034 node_ipam_controller.go:162] Starting ipam controller I0513 01:40:09.036044 shared_informer.go:197] Waiting for caches to sync for node I0513 01:40:09.041731 controllermanager.go:533] Started "persistentvolume-binder" I0513 01:40:09.041846 pv_controller_base.go:294] Starting persistent volume controller I0513 01:40:09.041856 shared_informer.go:197] Waiting for caches to sync for persistent volume I0513 01:40:09.047339 controllermanager.go:533] Started "replicaset" I0513 01:40:09.047438 replica_set.go:180] Starting replicaset controller I0513 01:40:09.047449 shared_informer.go:197] Waiting for caches to sync for ReplicaSet I0513 01:40:09.053552 controllermanager.go:533] Started "cronjob" W0513 01:40:09.053572 core.go:246] configure-cloud-routes is set, but no cloud provider specified. Will not configure cloud provider routes. W0513 01:40:09.053581 controllermanager.go:525] Skipping "route" I0513 01:40:09.053637 cronjob_controller.go:97] Starting CronJob Manager I0513 01:40:09.056662 node_lifecycle_controller.go:388] Sending events to api server. I0513 01:40:09.056788 node_lifecycle_controller.go:423] Controller is using taint based evictions. I0513 01:40:09.056855 taint_manager.go:162] Sending events to api server. I0513 01:40:09.056946 node_lifecycle_controller.go:520] Controller will reconcile labels. I0513 01:40:09.056984 controllermanager.go:533] Started "nodelifecycle" I0513 01:40:09.057072 node_lifecycle_controller.go:554] Starting node controller I0513 01:40:09.057079 shared_informer.go:197] Waiting for caches to sync for taint E0513 01:40:09.063873 core.go:91] Failed to start service controller: WARNING: no cloud provider provided, services of type LoadBalancer will fail W0513 01:40:09.063890 controllermanager.go:525] Skipping "service" I0513 01:40:09.070449 controllermanager.go:533] Started "replicationcontroller" I0513 01:40:09.070471 replica_set.go:180] Starting replicationcontroller controller I0513 01:40:09.070484 shared_informer.go:197] Waiting for caches to sync for ReplicationController time="2020-05-13T01:40:09.425398992+02:00" level=info msg="waiting for node sos CIDR not assigned yet" I0513 01:40:09.428890 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for statefulsets.apps I0513 01:40:09.428925 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for events.events.k8s.io I0513 01:40:09.428950 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for roles.rbac.authorization.k8s.io I0513 01:40:09.428977 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for addons.k3s.cattle.io I0513 01:40:09.429005 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for daemonsets.apps I0513 01:40:09.429023 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for poddisruptionbudgets.policy I0513 01:40:09.429053 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for deployments.apps I0513 01:40:09.429069 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for replicasets.apps I0513 01:40:09.429087 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for jobs.batch I0513 01:40:09.429107 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for ingresses.networking.k8s.io I0513 01:40:09.429125 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for helmcharts.helm.cattle.io W0513 01:40:09.429137 shared_informer.go:415] resyncPeriod 76465191653627 is smaller than resyncCheckPeriod 76681307783158 and the informer has already started. Changing it to 76681307783158 I0513 01:40:09.429339 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for serviceaccounts I0513 01:40:09.429373 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for podtemplates I0513 01:40:09.429394 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for horizontalpodautoscalers.autoscaling I0513 01:40:09.429413 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for networkpolicies.networking.k8s.io I0513 01:40:09.429443 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for rolebindings.rbac.authorization.k8s.io I0513 01:40:09.429463 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for endpointslices.discovery.k8s.io I0513 01:40:09.429478 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for leases.coordination.k8s.io W0513 01:40:09.429488 shared_informer.go:415] resyncPeriod 64991618986324 is smaller than resyncCheckPeriod 76681307783158 and the informer has already started. Changing it to 76681307783158 I0513 01:40:09.429642 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for limitranges I0513 01:40:09.429699 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for endpoints I0513 01:40:09.429757 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for ingresses.extensions I0513 01:40:09.429783 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for controllerrevisions.apps I0513 01:40:09.429836 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for cronjobs.batch I0513 01:40:09.429855 controllermanager.go:533] Started "resourcequota" I0513 01:40:09.429867 resource_quota_controller.go:271] Starting resource quota controller I0513 01:40:09.429897 shared_informer.go:197] Waiting for caches to sync for resource quota I0513 01:40:09.429934 resource_quota_monitor.go:303] QuotaMonitor running I0513 01:40:09.445928 controllermanager.go:533] Started "namespace" I0513 01:40:09.445996 namespace_controller.go:200] Starting namespace controller I0513 01:40:09.446006 shared_informer.go:197] Waiting for caches to sync for namespace I0513 01:40:09.451930 controllermanager.go:533] Started "daemonset" I0513 01:40:09.451952 daemon_controller.go:255] Starting daemon sets controller I0513 01:40:09.451961 shared_informer.go:197] Waiting for caches to sync for daemon sets I0513 01:40:09.457819 controllermanager.go:533] Started "ttl" I0513 01:40:09.457844 ttl_controller.go:116] Starting TTL controller I0513 01:40:09.457855 shared_informer.go:197] Waiting for caches to sync for TTL I0513 01:40:09.510350 controller.go:606] quota admission added evaluator for: leases.coordination.k8s.io I0513 01:40:10.289485 garbagecollector.go:129] Starting garbage collector controller I0513 01:40:10.289505 shared_informer.go:197] Waiting for caches to sync for garbage collector I0513 01:40:10.289524 graph_builder.go:282] GraphBuilder running I0513 01:40:10.289577 controllermanager.go:533] Started "garbagecollector" I0513 01:40:10.296063 controllermanager.go:533] Started "deployment" W0513 01:40:10.296077 controllermanager.go:512] "tokencleaner" is disabled I0513 01:40:10.296178 deployment_controller.go:152] Starting deployment controller I0513 01:40:10.296204 shared_informer.go:197] Waiting for caches to sync for deployment I0513 01:40:10.302126 controllermanager.go:533] Started "pvc-protection" W0513 01:40:10.302147 controllermanager.go:525] Skipping "root-ca-cert-publisher" I0513 01:40:10.302203 pvc_protection_controller.go:100] Starting PVC protection controller I0513 01:40:10.302216 shared_informer.go:197] Waiting for caches to sync for PVC protection I0513 01:40:10.308505 controllermanager.go:533] Started "clusterrole-aggregation" W0513 01:40:10.308527 controllermanager.go:525] Skipping "ttl-after-finished" W0513 01:40:10.308534 controllermanager.go:525] Skipping "endpointslice" I0513 01:40:10.308607 clusterroleaggregation_controller.go:148] Starting ClusterRoleAggregator I0513 01:40:10.308619 shared_informer.go:197] Waiting for caches to sync for ClusterRoleAggregator I0513 01:40:10.379645 controllermanager.go:533] Started "horizontalpodautoscaling" I0513 01:40:10.379739 horizontal.go:156] Starting HPA controller I0513 01:40:10.379746 shared_informer.go:197] Waiting for caches to sync for HPA I0513 01:40:10.580397 controllermanager.go:533] Started "disruption" I0513 01:40:10.580451 disruption.go:330] Starting disruption controller I0513 01:40:10.580456 shared_informer.go:197] Waiting for caches to sync for disruption I0513 01:40:10.630661 controllermanager.go:533] Started "csrsigning" I0513 01:40:10.630703 certificate_controller.go:118] Starting certificate controller "csrsigning" I0513 01:40:10.630709 shared_informer.go:197] Waiting for caches to sync for certificate-csrsigning I0513 01:40:10.782119 controllermanager.go:533] Started "persistentvolume-expander" I0513 01:40:10.782751 expand_controller.go:319] Starting expand controller I0513 01:40:10.782911 shared_informer.go:197] Waiting for caches to sync for expand W0513 01:40:10.792729 actual_state_of_world.go:506] Failed to update statusUpdateNeeded field in actual state of world: Failed to set statusUpdateNeeded to needed true, because nodeName="sos" does not exist I0513 01:40:10.796293 shared_informer.go:204] Caches are synced for deployment I0513 01:40:10.802170 shared_informer.go:204] Caches are synced for attach detach I0513 01:40:10.802342 shared_informer.go:204] Caches are synced for PVC protection I0513 01:40:10.808826 shared_informer.go:204] Caches are synced for ClusterRoleAggregator I0513 01:40:10.813982 shared_informer.go:204] Caches are synced for certificate-csrapproving I0513 01:40:10.822459 shared_informer.go:204] Caches are synced for service account I0513 01:40:10.830845 shared_informer.go:204] Caches are synced for certificate-csrsigning I0513 01:40:10.836210 shared_informer.go:204] Caches are synced for node I0513 01:40:10.836229 range_allocator.go:172] Starting range CIDR allocator I0513 01:40:10.836233 shared_informer.go:197] Waiting for caches to sync for cidrallocator I0513 01:40:10.836236 shared_informer.go:204] Caches are synced for cidrallocator I0513 01:40:10.838889 range_allocator.go:373] Set node sos PodCIDR to [10.42.0.0/24] I0513 01:40:10.842076 shared_informer.go:204] Caches are synced for persistent volume I0513 01:40:10.846202 shared_informer.go:204] Caches are synced for namespace I0513 01:40:10.847646 shared_informer.go:204] Caches are synced for ReplicaSet I0513 01:40:10.858115 shared_informer.go:204] Caches are synced for TTL I0513 01:40:10.870732 shared_informer.go:204] Caches are synced for ReplicationController I0513 01:40:10.880259 shared_informer.go:204] Caches are synced for PV protection I0513 01:40:10.883150 shared_informer.go:204] Caches are synced for expand I0513 01:40:10.891310 shared_informer.go:204] Caches are synced for GC I0513 01:40:10.892033 kuberuntime_manager.go:981] updating runtime config through cri with podcidr 10.42.0.0/24 I0513 01:40:10.892381 docker_service.go:356] docker cri received runtime config &RuntimeConfig{NetworkConfig:&NetworkConfig{PodCidr:10.42.0.0/24,},} I0513 01:40:10.892737 kubelet_network.go:77] Setting Pod CIDR: -> 10.42.0.0/24 I0513 01:40:10.979916 shared_informer.go:204] Caches are synced for HPA I0513 01:40:10.984288 controller.go:606] quota admission added evaluator for: replicasets.apps I0513 01:40:10.985831 shared_informer.go:204] Caches are synced for endpoint I0513 01:40:10.986555 event.go:281] Event(v1.ObjectReference{Kind:"Deployment", Namespace:"default", Name:"echoserver", UID:"08b83ae2-f291-4340-a18a-bfa43ec94400", APIVersion:"apps/v1", ResourceVersion:"221", FieldPath:""}): type: 'Normal' reason: 'ScalingReplicaSet' Scaled up replica set echoserver-5d8cc8d48 to 1 I0513 01:40:10.987669 event.go:281] Event(v1.ObjectReference{Kind:"Deployment", Namespace:"kube-system", Name:"coredns", UID:"90f25659-7d31-45fd-ad9d-d7b544d7ea9a", APIVersion:"apps/v1", ResourceVersion:"193", FieldPath:""}): type: 'Normal' reason: 'ScalingReplicaSet' Scaled up replica set coredns-6c6bb68b64 to 1 I0513 01:40:11.052232 shared_informer.go:204] Caches are synced for daemon sets I0513 01:40:11.057231 shared_informer.go:204] Caches are synced for taint I0513 01:40:11.057346 node_lifecycle_controller.go:1443] Initializing eviction metric for zone: I0513 01:40:11.057402 taint_manager.go:186] Starting NoExecuteTaintManager W0513 01:40:11.057424 node_lifecycle_controller.go:1058] Missing timestamp for Node sos. Assuming now as a timestamp. I0513 01:40:11.057451 node_lifecycle_controller.go:1259] Controller detected that zone is now in state Normal. I0513 01:40:11.057486 event.go:281] Event(v1.ObjectReference{Kind:"Node", Namespace:"", Name:"sos", UID:"a79b5976-6d04-4b02-bee0-d8942325da05", APIVersion:"", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'RegisteredNode' Node sos event: Registered Node sos in Controller E0513 01:40:11.084996 clusterroleaggregation_controller.go:180] admin failed with : Operation cannot be fulfilled on clusterroles.rbac.authorization.k8s.io "admin": the object has been modified; please apply your changes to the latest version and try again E0513 01:40:11.086350 clusterroleaggregation_controller.go:180] edit failed with : Operation cannot be fulfilled on clusterroles.rbac.authorization.k8s.io "edit": the object has been modified; please apply your changes to the latest version and try again E0513 01:40:11.090600 clusterroleaggregation_controller.go:180] edit failed with : Operation cannot be fulfilled on clusterroles.rbac.authorization.k8s.io "edit": the object has been modified; please apply your changes to the latest version and try again E0513 01:40:11.093334 clusterroleaggregation_controller.go:180] admin failed with : Operation cannot be fulfilled on clusterroles.rbac.authorization.k8s.io "admin": the object has been modified; please apply your changes to the latest version and try again I0513 01:40:11.275232 shared_informer.go:204] Caches are synced for stateful set I0513 01:40:11.279142 shared_informer.go:197] Waiting for caches to sync for resource quota I0513 01:40:11.280598 shared_informer.go:204] Caches are synced for disruption I0513 01:40:11.280609 disruption.go:338] Sending events to api server. I0513 01:40:11.379391 shared_informer.go:204] Caches are synced for resource quota I0513 01:40:11.386230 event.go:281] Event(v1.ObjectReference{Kind:"ReplicaSet", Namespace:"default", Name:"echoserver-5d8cc8d48", UID:"4e31f4e5-39a5-459f-884a-6352eff95af2", APIVersion:"apps/v1", ResourceVersion:"275", FieldPath:""}): type: 'Normal' reason: 'SuccessfulCreate' Created pod: echoserver-5d8cc8d48-bxsn5 I0513 01:40:11.387407 event.go:281] Event(v1.ObjectReference{Kind:"ReplicaSet", Namespace:"kube-system", Name:"coredns-6c6bb68b64", UID:"c49e937d-308a-4ce6-a607-b37d4e4ba924", APIVersion:"apps/v1", ResourceVersion:"276", FieldPath:""}): type: 'Normal' reason: 'SuccessfulCreate' Created pod: coredns-6c6bb68b64-mqv8t I0513 01:40:11.389674 shared_informer.go:204] Caches are synced for garbage collector I0513 01:40:11.389698 garbagecollector.go:138] Garbage collector: all resource monitors have synced. Proceeding to collect garbage I0513 01:40:11.390902 controller.go:606] quota admission added evaluator for: events.events.k8s.io I0513 01:40:11.392794 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "default-token-nch4k" (UniqueName: "kubernetes.io/secret/1fd8a837-ad17-49ca-a6a8-42462ad7e03b-default-token-nch4k") pod "echoserver-5d8cc8d48-bxsn5" (UID: "1fd8a837-ad17-49ca-a6a8-42462ad7e03b") I0513 01:40:11.408134 shared_informer.go:204] Caches are synced for job I0513 01:40:11.428178 flannel.go:92] Determining IP address of default interface I0513 01:40:11.428691 flannel.go:105] Using interface with name wlp2s0 and address 192.168.43.141 I0513 01:40:11.430067 shared_informer.go:204] Caches are synced for resource quota I0513 01:40:11.431545 kube.go:117] Waiting 10m0s for node controller to sync I0513 01:40:11.431597 kube.go:300] Starting kube subnet manager time="2020-05-13T01:40:11.440088415+02:00" level=info msg="labels have been set successfully on node: sos" I0513 01:40:11.451355 network_policy_controller.go:148] Starting network policy controller I0513 01:40:11.593366 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "config-volume" (UniqueName: "kubernetes.io/configmap/1df1fdb9-4f5a-4143-a0b4-1f9c70114cc0-config-volume") pod "coredns-6c6bb68b64-mqv8t" (UID: "1df1fdb9-4f5a-4143-a0b4-1f9c70114cc0") I0513 01:40:11.593409 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "coredns-token-mvbft" (UniqueName: "kubernetes.io/secret/1df1fdb9-4f5a-4143-a0b4-1f9c70114cc0-coredns-token-mvbft") pod "coredns-6c6bb68b64-mqv8t" (UID: "1df1fdb9-4f5a-4143-a0b4-1f9c70114cc0") I0513 01:40:11.782716 shared_informer.go:197] Waiting for caches to sync for garbage collector I0513 01:40:11.782768 shared_informer.go:204] Caches are synced for garbage collector E0513 01:40:12.115047 cni.go:364] Error adding kube-system_coredns-6c6bb68b64-mqv8t/92398d621eca376a43835976c6b5d16344213b24d6c999e0508815aff27966ce to network flannel/cbr0: failed to set bridge addr: could not add IP address to "cni0": file exists E0513 01:40:12.340439 remote_runtime.go:105] RunPodSandbox from runtime service failed: rpc error: code = Unknown desc = failed to set up sandbox container "92398d621eca376a43835976c6b5d16344213b24d6c999e0508815aff27966ce" network for pod "coredns-6c6bb68b64-mqv8t": networkPlugin cni failed to set up pod "coredns-6> E0513 01:40:12.340512 kuberuntime_sandbox.go:68] CreatePodSandbox for pod "coredns-6c6bb68b64-mqv8t_kube-system(1df1fdb9-4f5a-4143-a0b4-1f9c70114cc0)" failed: rpc error: code = Unknown desc = failed to set up sandbox container "92398d621eca376a43835976c6b5d16344213b24d6c999e0508815aff27966ce" network for pod "cored> E0513 01:40:12.340536 kuberuntime_manager.go:729] createPodSandbox for pod "coredns-6c6bb68b64-mqv8t_kube-system(1df1fdb9-4f5a-4143-a0b4-1f9c70114cc0)" failed: rpc error: code = Unknown desc = failed to set up sandbox container "92398d621eca376a43835976c6b5d16344213b24d6c999e0508815aff27966ce" network for pod "core> E0513 01:40:12.340617 pod_workers.go:191] Error syncing pod 1df1fdb9-4f5a-4143-a0b4-1f9c70114cc0 ("coredns-6c6bb68b64-mqv8t_kube-system(1df1fdb9-4f5a-4143-a0b4-1f9c70114cc0)"), skipping: failed to "CreatePodSandbox" for "coredns-6c6bb68b64-mqv8t_kube-system(1df1fdb9-4f5a-4143-a0b4-1f9c70114cc0)" with CreatePodSandb> I0513 01:40:12.431754 kube.go:124] Node controller sync successful I0513 01:40:12.431821 vxlan.go:121] VXLAN config: VNI=1 Port=0 GBP=false Learning=false DirectRouting=false I0513 01:40:12.466351 flannel.go:78] Wrote subnet file to /run/flannel/subnet.env I0513 01:40:12.466367 flannel.go:82] Running backend. I0513 01:40:12.466373 vxlan_network.go:60] watching for new subnet leases W0513 01:40:12.612167 docker_sandbox.go:394] failed to read pod IP from plugin/docker: networkPlugin cni failed on the status hook for pod "coredns-6c6bb68b64-mqv8t_kube-system": CNI failed to retrieve network namespace path: cannot find network namespace for the terminated container "92398d621eca376a43835976c6b5d1> W0513 01:40:12.613049 pod_container_deletor.go:75] Container "92398d621eca376a43835976c6b5d16344213b24d6c999e0508815aff27966ce" not found in pod's containers W0513 01:40:12.614550 cni.go:331] CNI failed to retrieve network namespace path: cannot find network namespace for the terminated container "92398d621eca376a43835976c6b5d16344213b24d6c999e0508815aff27966ce" I0513 01:40:12.996539 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "default-token-nch4k" (UniqueName: "kubernetes.io/secret/7a3d5f10-1747-4e1e-b0ef-da19e4c92970-default-token-nch4k") pod "busybox-without-access" (UID: "7a3d5f10-1747-4e1e-b0ef-da19e4c92970") I0513 01:40:17.813399 reconciler.go:183] operationExecutor.UnmountVolume started for volume "default-token-nch4k" (UniqueName: "kubernetes.io/secret/7a3d5f10-1747-4e1e-b0ef-da19e4c92970-default-token-nch4k") pod "7a3d5f10-1747-4e1e-b0ef-da19e4c92970" (UID: "7a3d5f10-1747-4e1e-b0ef-da19e4c92970") I0513 01:40:17.821887 operation_generator.go:713] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/7a3d5f10-1747-4e1e-b0ef-da19e4c92970-default-token-nch4k" (OuterVolumeSpecName: "default-token-nch4k") pod "7a3d5f10-1747-4e1e-b0ef-da19e4c92970" (UID: "7a3d5f10-1747-4e1e-b0ef-da19e4c92970"). InnerVo> I0513 01:40:17.913743 reconciler.go:303] Volume detached for volume "default-token-nch4k" (UniqueName: "kubernetes.io/secret/7a3d5f10-1747-4e1e-b0ef-da19e4c92970-default-token-nch4k") on node "sos" DevicePath "" W0513 01:40:18.699527 pod_container_deletor.go:75] Container "80452f51e0b49c1de0c6ac5b04fd10f2771d708ad5be7263d5c4765b9c1a840a" not found in pod's containers W0513 01:40:19.484194 kubelet_getters.go:297] Path "/var/lib/kubelet/pods/7a3d5f10-1747-4e1e-b0ef-da19e4c92970/volumes" does not exist I0513 01:42:18.254218 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "default-token-nch4k" (UniqueName: "kubernetes.io/secret/761ad939-bbc7-4f10-bf46-14f714e63f91-default-token-nch4k") pod "busybox-with-access" (UID: "761ad939-bbc7-4f10-bf46-14f714e63f91") W0513 01:42:18.661668 pod_container_deletor.go:75] Container "9375c84a9091dca65d4f67a64a633d22f9b1ccbdcc95a30bd36dcbd8760d9814" not found in pod's containers I0513 01:43:17.184490 reconciler.go:183] operationExecutor.UnmountVolume started for volume "default-token-nch4k" (UniqueName: "kubernetes.io/secret/761ad939-bbc7-4f10-bf46-14f714e63f91-default-token-nch4k") pod "761ad939-bbc7-4f10-bf46-14f714e63f91" (UID: "761ad939-bbc7-4f10-bf46-14f714e63f91") I0513 01:43:17.186451 operation_generator.go:713] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/761ad939-bbc7-4f10-bf46-14f714e63f91-default-token-nch4k" (OuterVolumeSpecName: "default-token-nch4k") pod "761ad939-bbc7-4f10-bf46-14f714e63f91" (UID: "761ad939-bbc7-4f10-bf46-14f714e63f91"). InnerVo> I0513 01:43:17.284740 reconciler.go:303] Volume detached for volume "default-token-nch4k" (UniqueName: "kubernetes.io/secret/761ad939-bbc7-4f10-bf46-14f714e63f91-default-token-nch4k") on node "sos" DevicePath "" W0513 01:43:17.488869 kubelet_getters.go:297] Path "/var/lib/kubelet/pods/761ad939-bbc7-4f10-bf46-14f714e63f91/volumes" does not exist W0513 01:43:18.093621 pod_container_deletor.go:75] Container "9375c84a9091dca65d4f67a64a633d22f9b1ccbdcc95a30bd36dcbd8760d9814" not found in pod's containers ```
Output of: k3s kubectl get events ``` LAST SEEN TYPE REASON OBJECT MESSAGE 3m51s Normal Starting node/sos Starting kubelet. 3m51s Normal NodeHasSufficientMemory node/sos Node sos status is now: NodeHasSufficientMemory 3m51s Normal NodeHasNoDiskPressure node/sos Node sos status is now: NodeHasNoDiskPressure 3m51s Normal NodeHasSufficientPID node/sos Node sos status is now: NodeHasSufficientPID 3m51s Normal NodeAllocatableEnforced node/sos Updated Node Allocatable limit across pods 3m50s Normal Starting node/sos Starting kube-proxy. 3m41s Normal NodeReady node/sos Node sos status is now: NodeReady 3m40s Normal ScalingReplicaSet deployment/echoserver Scaled up replica set echoserver-5d8cc8d48 to 1 3m39s Normal RegisteredNode node/sos Node sos event: Registered Node sos in Controller 3m39s Normal SuccessfulCreate replicaset/echoserver-5d8cc8d48 Created pod: echoserver-5d8cc8d48-bxsn5 Normal Scheduled pod/echoserver-5d8cc8d48-bxsn5 Successfully assigned default/echoserver-5d8cc8d48-bxsn5 to sos 3m38s Normal Pulled pod/echoserver-5d8cc8d48-bxsn5 Container image "gcr.io/google_containers/echoserver:1.10" already present on machine 3m38s Normal Created pod/echoserver-5d8cc8d48-bxsn5 Created container echoserver 3m38s Normal Started pod/echoserver-5d8cc8d48-bxsn5 Started container echoserver Normal Scheduled pod/busybox-without-access Successfully assigned default/busybox-without-access to sos 3m37s Normal Pulling pod/busybox-without-access Pulling image "busybox" 3m34s Normal Pulled pod/busybox-without-access Successfully pulled image "busybox" 3m34s Normal Created pod/busybox-without-access Created container busybox-without-access 3m34s Normal Started pod/busybox-without-access Started container busybox-without-access Normal Scheduled pod/busybox-with-access Successfully assigned default/busybox-with-access to sos 92s Normal Pulling pod/busybox-with-access Pulling image "busybox" 89s Normal Pulled pod/busybox-with-access Successfully pulled image "busybox" 89s Normal Created pod/busybox-with-access Created container busybox-with-access 89s Normal Started pod/busybox-with-access Started container busybox-with-access ```
Output of: k3s kubectl logs deploy/echoserver ``` Generating self-signed cert Generating a 2048 bit RSA private key ..............................................................................................+++ ............................................+++ writing new private key to '/certs/privateKey.key' ----- Starting nginx 10.42.0.5 - - [12/May/2020:23:40:16 +0000] "GET / HTTP/1.1" 200 434 "-" "Wget" 10.42.0.6 - - [12/May/2020:23:43:16 +0000] "GET / HTTP/1.1" 200 434 "-" "Wget" ```
consideRatio commented 4 years ago

Logs from using containerd (no --docker flag)

The bug reproduced in the same way.

Output of: journalctl -u k3s --since "10 minutes ago" ``` systemd[1]: Starting Lightweight Kubernetes... time="2020-05-13T02:00:43+02:00" level=info msg="Preparing data dir /var/lib/rancher/k3s/data/6a3098e6644f5f0dbfe14e5efa99bb8fdf60d63cae89fdffd71b7de11a1f1430" time="2020-05-13T02:00:45.049498527+02:00" level=info msg="Starting k3s v1.17.4+k3s1 (3eee8ac3)" time="2020-05-13T02:00:45.056077189+02:00" level=info msg="Kine listening on unix://kine.sock" time="2020-05-13T02:00:45.200729539+02:00" level=info msg="Active TLS secret (ver=) (count 7): map[listener.cattle.io/cn-10.43.0.1:10.43.0.1 listener.cattle.io/cn-127.0.0.1:127.0.0.1 listener.cattle.io/cn-192.168.43.141:192.168.43.141 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kub> time="2020-05-13T02:00:45.209798219+02:00" level=info msg="Running kube-apiserver --advertise-port=6443 --allow-privileged=true --anonymous-auth=false --api-audiences=unknown --authorization-mode=Node,RBAC --basic-auth-file=/var/lib/rancher/k3s/server/cred/passwd --bind-address=127.0.0.1 --cert-dir=/var/lib/rancher/k3s/ser> Flag --basic-auth-file has been deprecated, Basic authentication mode is deprecated and will be removed in a future release. It is not recommended for production environments. I0513 02:00:45.210668 server.go:622] external host was not specified, using 192.168.43.141 I0513 02:00:45.210951 server.go:163] Version: v1.17.4+k3s1 I0513 02:00:45.616111 plugins.go:158] Loaded 11 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,MutatingAdmissionWebhook,Runtim> I0513 02:00:45.616141 plugins.go:161] Loaded 7 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,Priority,PersistentVolumeClaimResize,ValidatingAdmissionWebhook,RuntimeClass,ResourceQuota. I0513 02:00:45.617288 plugins.go:158] Loaded 11 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,MutatingAdmissionWebhook,Runtim> I0513 02:00:45.617306 plugins.go:161] Loaded 7 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,Priority,PersistentVolumeClaimResize,ValidatingAdmissionWebhook,RuntimeClass,ResourceQuota. I0513 02:00:45.641042 master.go:267] Using reconciler: lease I0513 02:00:45.692832 rest.go:115] the default service ipfamily for this cluster is: IPv4 W0513 02:00:46.055957 genericapiserver.go:409] Skipping API batch/v2alpha1 because it has no resources. W0513 02:00:46.067204 genericapiserver.go:409] Skipping API discovery.k8s.io/v1alpha1 because it has no resources. W0513 02:00:46.079340 genericapiserver.go:409] Skipping API node.k8s.io/v1alpha1 because it has no resources. W0513 02:00:46.099131 genericapiserver.go:409] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources. W0513 02:00:46.103971 genericapiserver.go:409] Skipping API scheduling.k8s.io/v1alpha1 because it has no resources. W0513 02:00:46.120124 genericapiserver.go:409] Skipping API storage.k8s.io/v1alpha1 because it has no resources. W0513 02:00:46.148699 genericapiserver.go:409] Skipping API apps/v1beta2 because it has no resources. W0513 02:00:46.148743 genericapiserver.go:409] Skipping API apps/v1beta1 because it has no resources. I0513 02:00:46.162456 plugins.go:158] Loaded 11 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,MutatingAdmissionWebhook,Runtim> I0513 02:00:46.162481 plugins.go:161] Loaded 7 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,Priority,PersistentVolumeClaimResize,ValidatingAdmissionWebhook,RuntimeClass,ResourceQuota. I0513 02:00:48.358466 dynamic_cafile_content.go:166] Starting request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt I0513 02:00:48.358467 dynamic_cafile_content.go:166] Starting client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt I0513 02:00:48.358847 dynamic_serving_content.go:129] Starting serving-cert::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key I0513 02:00:48.359683 secure_serving.go:178] Serving securely on 127.0.0.1:6444 I0513 02:00:48.359777 autoregister_controller.go:140] Starting autoregister controller I0513 02:00:48.359781 controller.go:81] Starting OpenAPI AggregationController I0513 02:00:48.359785 cache.go:32] Waiting for caches to sync for autoregister controller I0513 02:00:48.359813 tlsconfig.go:219] Starting DynamicServingCertificateController I0513 02:00:48.359852 crd_finalizer.go:263] Starting CRDFinalizer I0513 02:00:48.359901 crdregistration_controller.go:111] Starting crd-autoregister controller I0513 02:00:48.359921 apiapproval_controller.go:185] Starting KubernetesAPIApprovalPolicyConformantConditionController I0513 02:00:48.359922 nonstructuralschema_controller.go:191] Starting NonStructuralSchemaConditionController I0513 02:00:48.359906 customresource_discovery_controller.go:208] Starting DiscoveryController I0513 02:00:48.359944 controller.go:85] Starting OpenAPI controller I0513 02:00:48.359947 establishing_controller.go:73] Starting EstablishingController I0513 02:00:48.359921 shared_informer.go:197] Waiting for caches to sync for crd-autoregister I0513 02:00:48.359970 available_controller.go:386] Starting AvailableConditionController I0513 02:00:48.359906 naming_controller.go:288] Starting NamingConditionController I0513 02:00:48.359981 cache.go:32] Waiting for caches to sync for AvailableConditionController controller I0513 02:00:48.359926 apiservice_controller.go:94] Starting APIServiceRegistrationController I0513 02:00:48.360020 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller I0513 02:00:48.360469 cluster_authentication_trust_controller.go:440] Starting cluster_authentication_trust_controller controller I0513 02:00:48.360483 shared_informer.go:197] Waiting for caches to sync for cluster_authentication_trust_controller I0513 02:00:48.360531 dynamic_cafile_content.go:166] Starting client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt I0513 02:00:48.360564 dynamic_cafile_content.go:166] Starting request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt E0513 02:00:48.379799 controller.go:150] Unable to perform initial Kubernetes service initialization: Service "kubernetes" is invalid: spec.clusterIP: Invalid value: "10.43.0.1": cannot allocate resources of type serviceipallocations at this time E0513 02:00:48.380538 controller.go:155] Unable to remove old endpoints from kubernetes service: StorageError: key not found, Code: 1, Key: /registry/masterleases/192.168.43.141, ResourceVersion: 0, AdditionalErrorMsg: I0513 02:00:48.459941 cache.go:39] Caches are synced for autoregister controller I0513 02:00:48.460071 cache.go:39] Caches are synced for AvailableConditionController controller I0513 02:00:48.460143 cache.go:39] Caches are synced for APIServiceRegistrationController controller I0513 02:00:48.460147 shared_informer.go:204] Caches are synced for crd-autoregister I0513 02:00:48.460630 shared_informer.go:204] Caches are synced for cluster_authentication_trust_controller I0513 02:00:49.358502 controller.go:107] OpenAPI AggregationController: Processing item I0513 02:00:49.358558 controller.go:130] OpenAPI AggregationController: action for item : Nothing (removed from the queue). I0513 02:00:49.358584 controller.go:130] OpenAPI AggregationController: action for item k8s_internal_local_delegation_chain_0000000000: Nothing (removed from the queue). I0513 02:00:49.366466 storage_scheduling.go:133] created PriorityClass system-node-critical with value 2000001000 I0513 02:00:49.369126 storage_scheduling.go:133] created PriorityClass system-cluster-critical with value 2000000000 I0513 02:00:49.369141 storage_scheduling.go:142] all system priority classes are created successfully or already exist. I0513 02:00:49.581817 controller.go:606] quota admission added evaluator for: roles.rbac.authorization.k8s.io I0513 02:00:49.607608 controller.go:606] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io W0513 02:00:49.706340 lease.go:224] Resetting endpoints for master service "kubernetes" to [192.168.43.141] I0513 02:00:49.706994 controller.go:606] quota admission added evaluator for: endpoints time="2020-05-13T02:00:50.368297075+02:00" level=info msg="Running kube-scheduler --bind-address=127.0.0.1 --kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --leader-elect=false --port=10251 --secure-port=0" time="2020-05-13T02:00:50.368753608+02:00" level=info msg="Running kube-controller-manager --allocate-node-cidrs=true --bind-address=127.0.0.1 --cluster-cidr=10.42.0.0/16 --cluster-signing-cert-file=/var/lib/rancher/k3s/server/tls/server-ca.crt --cluster-signing-key-file=/var/lib/rancher/k3s/server/tls/server-ca.key --kube> I0513 02:00:50.374159 controllermanager.go:161] Version: v1.17.4+k3s1 time="2020-05-13T02:00:50.374262232+02:00" level=info msg="Waiting for cloudcontroller rbac role to be created" I0513 02:00:50.374646 deprecated_insecure_serving.go:53] Serving insecurely on [::]:10252 time="2020-05-13T02:00:50.375220044+02:00" level=info msg="Creating CRD addons.k3s.cattle.io" W0513 02:00:50.379416 authorization.go:47] Authorization is disabled W0513 02:00:50.379439 authentication.go:92] Authentication is disabled I0513 02:00:50.379453 deprecated_insecure_serving.go:51] Serving healthz insecurely on [::]:10251 time="2020-05-13T02:00:50.380359833+02:00" level=info msg="Creating CRD helmcharts.helm.cattle.io" time="2020-05-13T02:00:50.388762369+02:00" level=info msg="Waiting for CRD helmcharts.helm.cattle.io to become available" I0513 02:00:50.686877 plugins.go:100] No cloud provider specified. I0513 02:00:50.688925 shared_informer.go:197] Waiting for caches to sync for tokens I0513 02:00:50.694919 controller.go:606] quota admission added evaluator for: serviceaccounts I0513 02:00:50.789324 shared_informer.go:204] Caches are synced for tokens time="2020-05-13T02:00:50.894872895+02:00" level=info msg="Done waiting for CRD helmcharts.helm.cattle.io to become available" time="2020-05-13T02:00:50.894895475+02:00" level=info msg="Waiting for CRD addons.k3s.cattle.io to become available" time="2020-05-13T02:00:51.378564860+02:00" level=info msg="Waiting for cloudcontroller rbac role to be created" time="2020-05-13T02:00:51.397539985+02:00" level=info msg="Done waiting for CRD addons.k3s.cattle.io to become available" time="2020-05-13T02:00:51.402681956+02:00" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-1.81.0.tgz" time="2020-05-13T02:00:51.402962314+02:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/coredns.yaml" time="2020-05-13T02:00:51.403050399+02:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml" time="2020-05-13T02:00:51.403165262+02:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml" I0513 02:00:51.407556 garbagecollector.go:129] Starting garbage collector controller I0513 02:00:51.407580 shared_informer.go:197] Waiting for caches to sync for garbage collector I0513 02:00:51.407644 graph_builder.go:282] GraphBuilder running I0513 02:00:51.407822 controllermanager.go:533] Started "garbagecollector" I0513 02:00:51.415743 controllermanager.go:533] Started "csrsigning" I0513 02:00:51.415772 certificate_controller.go:118] Starting certificate controller "csrsigning" I0513 02:00:51.415791 shared_informer.go:197] Waiting for caches to sync for certificate-csrsigning I0513 02:00:51.424508 controllermanager.go:533] Started "pvc-protection" I0513 02:00:51.424590 pvc_protection_controller.go:100] Starting PVC protection controller I0513 02:00:51.424606 shared_informer.go:197] Waiting for caches to sync for PVC protection I0513 02:00:51.432760 controllermanager.go:533] Started "endpoint" I0513 02:00:51.432800 endpoints_controller.go:181] Starting endpoint controller I0513 02:00:51.432815 shared_informer.go:197] Waiting for caches to sync for endpoint I0513 02:00:51.443833 controllermanager.go:533] Started "serviceaccount" I0513 02:00:51.443904 serviceaccounts_controller.go:116] Starting service account controller I0513 02:00:51.443915 shared_informer.go:197] Waiting for caches to sync for service account I0513 02:00:51.449975 controllermanager.go:533] Started "replicaset" W0513 02:00:51.449994 core.go:246] configure-cloud-routes is set, but no cloud provider specified. Will not configure cloud provider routes. W0513 02:00:51.450005 controllermanager.go:525] Skipping "route" I0513 02:00:51.450108 replica_set.go:180] Starting replicaset controller I0513 02:00:51.450119 shared_informer.go:197] Waiting for caches to sync for ReplicaSet I0513 02:00:51.457330 node_lifecycle_controller.go:77] Sending events to api server E0513 02:00:51.457398 core.go:232] failed to start cloud node lifecycle controller: no cloud provider provided W0513 02:00:51.457412 controllermanager.go:525] Skipping "cloud-node-lifecycle" I0513 02:00:51.466727 controllermanager.go:533] Started "replicationcontroller" I0513 02:00:51.466846 replica_set.go:180] Starting replicationcontroller controller I0513 02:00:51.466884 shared_informer.go:197] Waiting for caches to sync for ReplicationController time="2020-05-13T02:00:51.506865982+02:00" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller" time="2020-05-13T02:00:51.506996979+02:00" level=info msg="Waiting for master node startup: resource name may not be empty" time="2020-05-13T02:00:51.506872974+02:00" level=info msg="Node token is available at /var/lib/rancher/k3s/server/token" time="2020-05-13T02:00:51.507171751+02:00" level=info msg="To join node to cluster: k3s agent -s https://192.168.43.141:6443 -t ${NODE_TOKEN}" I0513 02:00:51.536184 controller.go:606] quota admission added evaluator for: addons.k3s.cattle.io http: TLS handshake error from 127.0.0.1:35826: remote error: tls: bad certificate time="2020-05-13T02:00:51.591742427+02:00" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml" time="2020-05-13T02:00:51.591774184+02:00" level=info msg="Run: k3s kubectl" time="2020-05-13T02:00:51.591781874+02:00" level=info msg="k3s is up and running" time="2020-05-13T02:00:51.591972162+02:00" level=info msg="module overlay was already loaded" time="2020-05-13T02:00:51.591994989+02:00" level=info msg="module nf_conntrack was already loaded" time="2020-05-13T02:00:51.592012796+02:00" level=info msg="module br_netfilter was already loaded" systemd[1]: Started Lightweight Kubernetes. I0513 02:00:51.593418 controller.go:606] quota admission added evaluator for: deployments.apps http: TLS handshake error from 127.0.0.1:35834: remote error: tls: bad certificate http: TLS handshake error from 127.0.0.1:35840: remote error: tls: bad certificate time="2020-05-13T02:00:51.608165280+02:00" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller" time="2020-05-13T02:00:51.608210669+02:00" level=info msg="Starting batch/v1, Kind=Job controller" time="2020-05-13T02:00:51.608217302+02:00" level=info msg="Starting /v1, Kind=Pod controller" time="2020-05-13T02:00:51.608224576+02:00" level=info msg="Starting /v1, Kind=Node controller" time="2020-05-13T02:00:51.608227540+02:00" level=info msg="Starting /v1, Kind=Service controller" time="2020-05-13T02:00:51.608227525+02:00" level=info msg="Starting /v1, Kind=Endpoints controller" time="2020-05-13T02:00:51.622169234+02:00" level=info msg="Logging containerd to /var/lib/rancher/k3s/agent/containerd/containerd.log" time="2020-05-13T02:00:51.622324129+02:00" level=info msg="Running containerd -c /var/lib/rancher/k3s/agent/etc/containerd/config.toml -a /run/k3s/containerd/containerd.sock --state /run/k3s/containerd --root /var/lib/rancher/k3s/agent/containerd" time="2020-05-13T02:00:51.622433451+02:00" level=info msg="Waiting for containerd startup: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: Error while dialing dial unix /run/k3s/containerd/containerd.sock: connect: connection refused\> I0513 02:00:51.825336 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for statefulsets.apps I0513 02:00:51.825372 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for events.events.k8s.io I0513 02:00:51.825387 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for networkpolicies.networking.k8s.io I0513 02:00:51.825409 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for addons.k3s.cattle.io I0513 02:00:51.825432 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for horizontalpodautoscalers.autoscaling I0513 02:00:51.825467 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for ingresses.networking.k8s.io I0513 02:00:51.825484 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for poddisruptionbudgets.policy W0513 02:00:51.825504 shared_informer.go:415] resyncPeriod 80933456379810 is smaller than resyncCheckPeriod 82083089154217 and the informer has already started. Changing it to 82083089154217 I0513 02:00:51.825789 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for replicasets.apps I0513 02:00:51.825828 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for controllerrevisions.apps I0513 02:00:51.825846 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for rolebindings.rbac.authorization.k8s.io I0513 02:00:51.825875 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for roles.rbac.authorization.k8s.io I0513 02:00:51.825913 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for helmcharts.helm.cattle.io I0513 02:00:51.825935 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for endpoints I0513 02:00:51.825949 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for jobs.batch I0513 02:00:51.825962 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for limitranges W0513 02:00:51.825969 shared_informer.go:415] resyncPeriod 56267966702004 is smaller than resyncCheckPeriod 82083089154217 and the informer has already started. Changing it to 82083089154217 I0513 02:00:51.826100 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for serviceaccounts I0513 02:00:51.826132 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for daemonsets.apps I0513 02:00:51.826153 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for podtemplates I0513 02:00:51.826170 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for cronjobs.batch I0513 02:00:51.826225 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for ingresses.extensions I0513 02:00:51.826246 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for deployments.apps I0513 02:00:51.826262 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for leases.coordination.k8s.io I0513 02:00:51.826277 resource_quota_monitor.go:228] QuotaMonitor created object count evaluator for endpointslices.discovery.k8s.io I0513 02:00:51.826289 controllermanager.go:533] Started "resourcequota" I0513 02:00:51.826300 resource_quota_controller.go:271] Starting resource quota controller I0513 02:00:51.826314 shared_informer.go:197] Waiting for caches to sync for resource quota I0513 02:00:51.826329 resource_quota_monitor.go:303] QuotaMonitor running I0513 02:00:51.829256 node_lifecycle_controller.go:388] Sending events to api server. I0513 02:00:51.829387 node_lifecycle_controller.go:423] Controller is using taint based evictions. I0513 02:00:51.829439 taint_manager.go:162] Sending events to api server. I0513 02:00:51.829498 node_lifecycle_controller.go:520] Controller will reconcile labels. I0513 02:00:51.829516 controllermanager.go:533] Started "nodelifecycle" I0513 02:00:51.829592 node_lifecycle_controller.go:554] Starting node controller I0513 02:00:51.829604 shared_informer.go:197] Waiting for caches to sync for taint E0513 02:00:51.835310 core.go:91] Failed to start service controller: WARNING: no cloud provider provided, services of type LoadBalancer will fail W0513 02:00:51.835325 controllermanager.go:525] Skipping "service" I0513 02:00:51.843054 controllermanager.go:533] Started "persistentvolume-binder" I0513 02:00:51.843076 pv_controller_base.go:294] Starting persistent volume controller I0513 02:00:51.843087 shared_informer.go:197] Waiting for caches to sync for persistent volume I0513 02:00:51.856678 controllermanager.go:533] Started "attachdetach" I0513 02:00:51.856936 attach_detach_controller.go:342] Starting attach detach controller I0513 02:00:51.856961 shared_informer.go:197] Waiting for caches to sync for attach detach I0513 02:00:51.868774 controllermanager.go:533] Started "pv-protection" W0513 02:00:51.869176 controllermanager.go:525] Skipping "endpointslice" I0513 02:00:51.868813 pv_protection_controller.go:81] Starting PV protection controller I0513 02:00:51.869245 shared_informer.go:197] Waiting for caches to sync for PV protection I0513 02:00:52.012359 controllermanager.go:533] Started "podgc" I0513 02:00:52.012409 gc_controller.go:88] Starting GC controller I0513 02:00:52.012415 shared_informer.go:197] Waiting for caches to sync for GC I0513 02:00:52.162060 controllermanager.go:533] Started "daemonset" I0513 02:00:52.162105 daemon_controller.go:255] Starting daemon sets controller I0513 02:00:52.162112 shared_informer.go:197] Waiting for caches to sync for daemon sets time="2020-05-13T02:00:52.306816140+02:00" level=info msg="Starting /v1, Kind=Secret controller" time="2020-05-13T02:00:52.309982021+02:00" level=info msg="Active TLS secret k3s-serving (ver=219) (count 7): map[listener.cattle.io/cn-10.43.0.1:10.43.0.1 listener.cattle.io/cn-127.0.0.1:127.0.0.1 listener.cattle.io/cn-192.168.43.141:192.168.43.141 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernet> I0513 02:00:52.311442 controllermanager.go:533] Started "ttl" I0513 02:00:52.311533 ttl_controller.go:116] Starting TTL controller I0513 02:00:52.311544 shared_informer.go:197] Waiting for caches to sync for TTL I0513 02:00:52.361400 node_ipam_controller.go:94] Sending events to api server. time="2020-05-13T02:00:52.382772567+02:00" level=info msg="Running cloud-controller-manager --allocate-node-cidrs=true --allow-untagged-cloud=true --bind-address=127.0.0.1 --cloud-provider=k3s --cluster-cidr=10.42.0.0/16 --kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --leader-elect=false --node-s> Flag --allow-untagged-cloud has been deprecated, This flag is deprecated and will be removed in a future release. A cluster-id will be required on cloud instances. I0513 02:00:52.386417 controllermanager.go:120] Version: v1.17.4+k3s1 W0513 02:00:52.386434 controllermanager.go:132] detected a cluster without a ClusterID. A ClusterID will be required in the future. Please tag your cluster to avoid any future issues I0513 02:00:52.389288 node_controller.go:110] Sending events to api server. I0513 02:00:52.389395 controllermanager.go:247] Started "cloud-node" I0513 02:00:52.390620 node_lifecycle_controller.go:77] Sending events to api server I0513 02:00:52.390671 controllermanager.go:247] Started "cloud-node-lifecycle" E0513 02:00:52.392432 core.go:90] Failed to start service controller: the cloud provider does not support external load balancers W0513 02:00:52.392454 controllermanager.go:244] Skipping "service" W0513 02:00:52.392462 core.go:108] configure-cloud-routes is set, but cloud provider does not support routes. Will not configure cloud provider routes. W0513 02:00:52.392466 controllermanager.go:244] Skipping "route" time="2020-05-13T02:00:52.510064457+02:00" level=info msg="Waiting for master node sos startup: nodes \"sos\" not found" time="2020-05-13T02:00:52.635958188+02:00" level=info msg="Connecting to proxy" url="wss://192.168.43.141:6443/v1-k3s/connect" time="2020-05-13T02:00:52.638546043+02:00" level=info msg="Handling backend connection request [sos]" time="2020-05-13T02:00:52.639960481+02:00" level=info msg="Running kubelet --address=0.0.0.0 --anonymous-auth=false --authentication-token-webhook=true --authorization-mode=Webhook --cgroup-driver=cgroupfs --client-ca-file=/var/lib/rancher/k3s/agent/client-ca.crt --cloud-provider=external --cluster-dns=10.43.0.10 --cluster> Flag --containerd has been deprecated, This is a cadvisor flag that was mistakenly registered with the Kubelet. Due to legacy concerns, it will follow the standard CLI deprecation timeline before being removed. time="2020-05-13T02:00:52.640087178+02:00" level=info msg="Running kube-proxy --cluster-cidr=10.42.0.0/16 --healthz-bind-address=127.0.0.1 --hostname-override=sos --kubeconfig=/var/lib/rancher/k3s/agent/kubeproxy.kubeconfig --proxy-mode=iptables" W0513 02:00:52.640216 server.go:213] WARNING: all flags other than --config, --write-config-to, and --cleanup are deprecated. Please begin using a config file ASAP. time="2020-05-13T02:00:52.649398701+02:00" level=info msg="waiting for node sos: nodes \"sos\" not found" I0513 02:00:52.657665 server.go:412] Version: v1.17.4+k3s1 E0513 02:00:52.665129 node.go:124] Failed to retrieve node info: nodes "sos" not found I0513 02:00:52.670533 server.go:639] --cgroups-per-qos enabled, but --cgroup-root was not specified. defaulting to / I0513 02:00:52.671204 container_manager_linux.go:271] container manager verified user specified cgroup-root exists: [] I0513 02:00:52.671227 container_manager_linux.go:276] Creating Container Manager object based on Node Config: {RuntimeCgroupsName:/systemd/system.slice SystemCgroupsName: KubeletCgroupsName:/systemd/system.slice ContainerRuntime:remote CgroupsPerQOS:true CgroupRoot:/ CgroupDriver:cgroupfs KubeletRootDir:/var/lib/ku> I0513 02:00:52.671352 fake_topology_manager.go:29] [fake topologymanager] NewFakeManager I0513 02:00:52.671360 container_manager_linux.go:311] Creating device plugin manager: true I0513 02:00:52.671443 fake_topology_manager.go:39] [fake topologymanager] AddHintProvider HintProvider: &{kubelet.sock /var/lib/kubelet/device-plugins/ map[] {0 0} {{} [0 0 0]} 0x2c49910 0x6dd8210 0x2c4a1e0 map[] map[] map[] map[] map[] 0xc00d31df50 [0] 0x6dd8210} I0513 02:00:52.671486 state_mem.go:36] [cpumanager] initializing new in-memory state store I0513 02:00:52.672942 fake_topology_manager.go:39] [fake topologymanager] AddHintProvider HintProvider: &{{0 0} 0x6dd8210 10000000000 0xc005cc1e60 map[] 0x6dd8210} I0513 02:00:52.673635 kubelet.go:311] Watching apiserver W0513 02:00:52.675597 util_unix.go:103] Using "/run/k3s/containerd/containerd.sock" as endpoint is deprecated, please consider using full url format "unix:///run/k3s/containerd/containerd.sock". W0513 02:00:52.675809 util_unix.go:103] Using "/run/k3s/containerd/containerd.sock" as endpoint is deprecated, please consider using full url format "unix:///run/k3s/containerd/containerd.sock". I0513 02:00:52.677357 kuberuntime_manager.go:211] Container runtime containerd initialized, version: v1.3.3-k3s2, apiVersion: v1alpha2 I0513 02:00:52.677872 server.go:1111] Started kubelet I0513 02:00:52.677915 server.go:144] Starting to listen on 0.0.0.0:10250 I0513 02:00:52.679395 server.go:384] Adding debug handlers to kubelet server. I0513 02:00:52.679813 fs_resource_analyzer.go:64] Starting FS ResourceAnalyzer I0513 02:00:52.680065 volume_manager.go:265] Starting Kubelet Volume Manager I0513 02:00:52.680149 desired_state_of_world_populator.go:138] Desired state populator starts to run E0513 02:00:52.683605 cri_stats_provider.go:375] Failed to get the info of the filesystem with mountpoint "/var/lib/rancher/k3s/agent/containerd/io.containerd.snapshotter.v1.overlayfs": unable to find data in memory cache. E0513 02:00:52.683644 kubelet.go:1302] Image garbage collection failed once. Stats initialization may not have completed yet: invalid capacity 0 on image filesystem E0513 02:00:52.690444 controller.go:227] failed to get node "sos" when trying to set owner ref to the node lease: nodes "sos" not found I0513 02:00:52.752971 status_manager.go:157] Starting to sync pod status with apiserver I0513 02:00:52.753013 kubelet.go:1820] Starting kubelet main sync loop. E0513 02:00:52.753057 kubelet.go:1844] skipping pod synchronization - [container runtime status check may not have completed yet, PLEG is not healthy: pleg has yet to be successful] I0513 02:00:52.780161 kubelet_node_status.go:294] Setting node annotation to enable volume controller attach/detach E0513 02:00:52.780206 kubelet.go:2263] node "sos" not found I0513 02:00:52.782530 kubelet_node_status.go:70] Attempting to register node sos I0513 02:00:52.845059 kubelet_node_status.go:294] Setting node annotation to enable volume controller attach/detach I0513 02:00:52.846866 cpu_manager.go:173] [cpumanager] starting with none policy I0513 02:00:52.846890 cpu_manager.go:174] [cpumanager] reconciling every 10s I0513 02:00:52.846899 policy_none.go:43] [cpumanager] none policy: Start W0513 02:00:52.847879 manager.go:577] Failed to retrieve checkpoint for "kubelet_internal_checkpoint": checkpoint is not found I0513 02:00:52.848118 plugin_manager.go:114] Starting Kubelet Plugin Manager E0513 02:00:52.848702 eviction_manager.go:246] eviction manager: failed to get summary stats: failed to get node info: node "sos" not found E0513 02:00:52.880358 kubelet.go:2263] node "sos" not found I0513 02:00:52.880523 reconciler.go:156] Reconciler: start to sync state E0513 02:00:52.980577 kubelet.go:2263] node "sos" not found I0513 02:00:53.077753 kubelet_node_status.go:73] Successfully registered node sos time="2020-05-13T02:00:53.080826836+02:00" level=info msg="couldn't find node internal ip label on node sos" time="2020-05-13T02:00:53.080854705+02:00" level=info msg="couldn't find node hostname label on node sos" time="2020-05-13T02:00:53.083722607+02:00" level=info msg="couldn't find node internal ip label on node sos" time="2020-05-13T02:00:53.083760206+02:00" level=info msg="couldn't find node hostname label on node sos" I0513 02:00:53.083783 node_controller.go:424] Successfully initialized node sos with cloud provider time="2020-05-13T02:00:53.088517203+02:00" level=info msg="Updated coredns node hosts entry [192.168.43.141 sos]" time="2020-05-13T02:00:53.516318794+02:00" level=info msg="master role label has been set succesfully on node: sos" I0513 02:00:53.566773 controller.go:606] quota admission added evaluator for: networkpolicies.networking.k8s.io I0513 02:00:53.694391 node.go:135] Successfully retrieved node IP: 192.168.43.141 I0513 02:00:53.694417 server_others.go:146] Using iptables Proxier. I0513 02:00:53.695046 server.go:571] Version: v1.17.4+k3s1 I0513 02:00:53.695611 conntrack.go:52] Setting nf_conntrack_max to 393216 I0513 02:00:53.695870 config.go:131] Starting endpoints config controller I0513 02:00:53.695890 config.go:313] Starting service config controller I0513 02:00:53.695901 shared_informer.go:197] Waiting for caches to sync for endpoints config I0513 02:00:53.695905 shared_informer.go:197] Waiting for caches to sync for service config I0513 02:00:53.796077 shared_informer.go:204] Caches are synced for service config I0513 02:00:53.796077 shared_informer.go:204] Caches are synced for endpoints config time="2020-05-13T02:00:54.653431871+02:00" level=info msg="waiting for node sos CIDR not assigned yet" W0513 02:00:54.764473 kubelet_getters.go:297] Path "/var/lib/kubelet/pods/1fd8a837-ad17-49ca-a6a8-42462ad7e03b/volumes" does not exist W0513 02:00:54.764514 kubelet_getters.go:297] Path "/var/lib/kubelet/pods/1df1fdb9-4f5a-4143-a0b4-1f9c70114cc0/volumes" does not exist time="2020-05-13T02:00:56.656393713+02:00" level=info msg="waiting for node sos CIDR not assigned yet" time="2020-05-13T02:00:58.661231762+02:00" level=info msg="waiting for node sos CIDR not assigned yet" time="2020-05-13T02:01:00.667733790+02:00" level=info msg="waiting for node sos CIDR not assigned yet" I0513 02:01:02.372614 range_allocator.go:82] Sending events to api server. I0513 02:01:02.372724 range_allocator.go:110] No Service CIDR provided. Skipping filtering out service addresses. I0513 02:01:02.372732 range_allocator.go:116] No Secondary Service CIDR provided. Skipping filtering out secondary service addresses. I0513 02:01:02.372753 controllermanager.go:533] Started "nodeipam" I0513 02:01:02.372828 node_ipam_controller.go:162] Starting ipam controller I0513 02:01:02.372838 shared_informer.go:197] Waiting for caches to sync for node I0513 02:01:02.378005 controllermanager.go:533] Started "deployment" I0513 02:01:02.378119 deployment_controller.go:152] Starting deployment controller I0513 02:01:02.378131 shared_informer.go:197] Waiting for caches to sync for deployment I0513 02:01:02.390079 controllermanager.go:533] Started "horizontalpodautoscaling" I0513 02:01:02.390171 horizontal.go:156] Starting HPA controller I0513 02:01:02.390178 shared_informer.go:197] Waiting for caches to sync for HPA I0513 02:01:02.396000 controllermanager.go:533] Started "cronjob" I0513 02:01:02.396079 cronjob_controller.go:97] Starting CronJob Manager I0513 02:01:02.398696 controllermanager.go:533] Started "csrapproving" I0513 02:01:02.398801 certificate_controller.go:118] Starting certificate controller "csrapproving" I0513 02:01:02.398810 shared_informer.go:197] Waiting for caches to sync for certificate-csrapproving I0513 02:01:02.406087 controllermanager.go:533] Started "persistentvolume-expander" I0513 02:01:02.406133 expand_controller.go:319] Starting expand controller W0513 02:01:02.406135 controllermanager.go:525] Skipping "ttl-after-finished" I0513 02:01:02.406142 shared_informer.go:197] Waiting for caches to sync for expand I0513 02:01:02.423443 controllermanager.go:533] Started "namespace" I0513 02:01:02.423512 namespace_controller.go:200] Starting namespace controller I0513 02:01:02.423525 shared_informer.go:197] Waiting for caches to sync for namespace I0513 02:01:02.429270 controllermanager.go:533] Started "job" I0513 02:01:02.429359 job_controller.go:143] Starting job controller I0513 02:01:02.429366 shared_informer.go:197] Waiting for caches to sync for job I0513 02:01:02.431471 controllermanager.go:533] Started "csrcleaner" W0513 02:01:02.431482 controllermanager.go:512] "tokencleaner" is disabled I0513 02:01:02.431542 cleaner.go:81] Starting CSR cleaner controller I0513 02:01:02.517534 controllermanager.go:533] Started "disruption" W0513 02:01:02.517578 controllermanager.go:512] "bootstrapsigner" is disabled I0513 02:01:02.517625 disruption.go:330] Starting disruption controller I0513 02:01:02.517657 shared_informer.go:197] Waiting for caches to sync for disruption I0513 02:01:02.668735 controllermanager.go:533] Started "clusterrole-aggregation" W0513 02:01:02.668755 controllermanager.go:525] Skipping "root-ca-cert-publisher" I0513 02:01:02.668785 clusterroleaggregation_controller.go:148] Starting ClusterRoleAggregator I0513 02:01:02.668790 shared_informer.go:197] Waiting for caches to sync for ClusterRoleAggregator time="2020-05-13T02:01:02.670058551+02:00" level=info msg="waiting for node sos CIDR not assigned yet" I0513 02:01:02.694713 controller.go:606] quota admission added evaluator for: leases.coordination.k8s.io I0513 02:01:02.816694 controllermanager.go:533] Started "statefulset" I0513 02:01:02.817140 stateful_set.go:145] Starting stateful set controller I0513 02:01:02.817155 shared_informer.go:197] Waiting for caches to sync for stateful set I0513 02:01:02.817507 shared_informer.go:197] Waiting for caches to sync for garbage collector I0513 02:01:02.818525 shared_informer.go:197] Waiting for caches to sync for resource quota I0513 02:01:02.829474 shared_informer.go:204] Caches are synced for job I0513 02:01:02.833048 shared_informer.go:204] Caches are synced for endpoint I0513 02:01:02.850398 shared_informer.go:204] Caches are synced for ReplicaSet I0513 02:01:02.868904 shared_informer.go:204] Caches are synced for ClusterRoleAggregator I0513 02:01:02.878298 shared_informer.go:204] Caches are synced for deployment I0513 02:01:02.890456 shared_informer.go:204] Caches are synced for HPA I0513 02:01:02.899065 shared_informer.go:204] Caches are synced for certificate-csrapproving I0513 02:01:02.915950 shared_informer.go:204] Caches are synced for certificate-csrsigning I0513 02:01:02.923633 shared_informer.go:204] Caches are synced for namespace I0513 02:01:02.943995 shared_informer.go:204] Caches are synced for service account E0513 02:01:03.123149 clusterroleaggregation_controller.go:180] edit failed with : Operation cannot be fulfilled on clusterroles.rbac.authorization.k8s.io "edit": the object has been modified; please apply your changes to the latest version and try again E0513 02:01:03.123440 clusterroleaggregation_controller.go:180] admin failed with : Operation cannot be fulfilled on clusterroles.rbac.authorization.k8s.io "admin": the object has been modified; please apply your changes to the latest version and try again I0513 02:01:03.124786 shared_informer.go:204] Caches are synced for PVC protection E0513 02:01:03.128620 clusterroleaggregation_controller.go:180] admin failed with : Operation cannot be fulfilled on clusterroles.rbac.authorization.k8s.io "admin": the object has been modified; please apply your changes to the latest version and try again E0513 02:01:03.132937 clusterroleaggregation_controller.go:180] admin failed with : Operation cannot be fulfilled on clusterroles.rbac.authorization.k8s.io "admin": the object has been modified; please apply your changes to the latest version and try again I0513 02:01:03.168012 controller.go:606] quota admission added evaluator for: replicasets.apps I0513 02:01:03.169826 event.go:281] Event(v1.ObjectReference{Kind:"Deployment", Namespace:"default", Name:"echoserver", UID:"bc56b621-2410-462e-951d-25f993f8a8d2", APIVersion:"apps/v1", ResourceVersion:"241", FieldPath:""}): type: 'Normal' reason: 'ScalingReplicaSet' Scaled up replica set echoserver-5d8cc8d48 to 1 I0513 02:01:03.170510 event.go:281] Event(v1.ObjectReference{Kind:"Deployment", Namespace:"kube-system", Name:"coredns", UID:"13445d89-8110-422b-bade-41e472e292e2", APIVersion:"apps/v1", ResourceVersion:"193", FieldPath:""}): type: 'Normal' reason: 'ScalingReplicaSet' Scaled up replica set coredns-6c6bb68b64 to 1 I0513 02:01:03.217274 shared_informer.go:204] Caches are synced for stateful set I0513 02:01:03.217827 shared_informer.go:204] Caches are synced for disruption I0513 02:01:03.217840 disruption.go:338] Sending events to api server. I0513 02:01:03.267205 shared_informer.go:204] Caches are synced for ReplicationController W0513 02:01:03.268978 actual_state_of_world.go:506] Failed to update statusUpdateNeeded field in actual state of world: Failed to set statusUpdateNeeded to needed true, because nodeName="sos" does not exist I0513 02:01:03.273059 shared_informer.go:204] Caches are synced for node I0513 02:01:03.273101 range_allocator.go:172] Starting range CIDR allocator I0513 02:01:03.273105 shared_informer.go:197] Waiting for caches to sync for cidrallocator I0513 02:01:03.273109 shared_informer.go:204] Caches are synced for cidrallocator I0513 02:01:03.276435 range_allocator.go:373] Set node sos PodCIDR to [10.42.0.0/24] I0513 02:01:03.304830 kuberuntime_manager.go:981] updating runtime config through cri with podcidr 10.42.0.0/24 I0513 02:01:03.306102 kubelet_network.go:77] Setting Pod CIDR: -> 10.42.0.0/24 I0513 02:01:03.311754 shared_informer.go:204] Caches are synced for TTL I0513 02:01:03.312573 shared_informer.go:204] Caches are synced for GC I0513 02:01:03.320912 event.go:281] Event(v1.ObjectReference{Kind:"ReplicaSet", Namespace:"default", Name:"echoserver-5d8cc8d48", UID:"cf5486fe-fc9e-4e5b-98ce-e0e3c3a166c7", APIVersion:"apps/v1", ResourceVersion:"283", FieldPath:""}): type: 'Normal' reason: 'SuccessfulCreate' Created pod: echoserver-5d8cc8d48-ckd5t I0513 02:01:03.321372 event.go:281] Event(v1.ObjectReference{Kind:"ReplicaSet", Namespace:"kube-system", Name:"coredns-6c6bb68b64", UID:"1ba062ef-3411-4eb6-95ce-e0950cc3ded2", APIVersion:"apps/v1", ResourceVersion:"284", FieldPath:""}): type: 'Normal' reason: 'SuccessfulCreate' Created pod: coredns-6c6bb68b64-2vmq5 I0513 02:01:03.322970 controller.go:606] quota admission added evaluator for: events.events.k8s.io I0513 02:01:03.329705 shared_informer.go:204] Caches are synced for taint I0513 02:01:03.329770 node_lifecycle_controller.go:1443] Initializing eviction metric for zone: I0513 02:01:03.329796 taint_manager.go:186] Starting NoExecuteTaintManager W0513 02:01:03.329822 node_lifecycle_controller.go:1058] Missing timestamp for Node sos. Assuming now as a timestamp. I0513 02:01:03.329849 node_lifecycle_controller.go:1259] Controller detected that zone is now in state Normal. I0513 02:01:03.329915 event.go:281] Event(v1.ObjectReference{Kind:"Node", Namespace:"", Name:"sos", UID:"7a0d3bdf-8276-48c1-9dcb-078e51503337", APIVersion:"", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'RegisteredNode' Node sos event: Registered Node sos in Controller I0513 02:01:03.343148 shared_informer.go:204] Caches are synced for persistent volume I0513 02:01:03.357364 shared_informer.go:204] Caches are synced for attach detach I0513 02:01:03.362276 shared_informer.go:204] Caches are synced for daemon sets I0513 02:01:03.369408 shared_informer.go:204] Caches are synced for PV protection I0513 02:01:03.406343 shared_informer.go:204] Caches are synced for expand I0513 02:01:03.407981 shared_informer.go:204] Caches are synced for garbage collector I0513 02:01:03.408030 garbagecollector.go:138] Garbage collector: all resource monitors have synced. Proceeding to collect garbage I0513 02:01:03.417795 shared_informer.go:204] Caches are synced for garbage collector I0513 02:01:03.418695 shared_informer.go:204] Caches are synced for resource quota I0513 02:01:03.426468 shared_informer.go:204] Caches are synced for resource quota I0513 02:01:04.509196 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "default-token-6d87q" (UniqueName: "kubernetes.io/secret/31e75204-ce2d-4b90-bfad-8d9403475d0a-default-token-6d87q") pod "echoserver-5d8cc8d48-ckd5t" (UID: "31e75204-ce2d-4b90-bfad-8d9403475d0a") I0513 02:01:04.509319 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "config-volume" (UniqueName: "kubernetes.io/configmap/bbf8d805-5576-4c5f-b548-a4a560c4a32d-config-volume") pod "coredns-6c6bb68b64-2vmq5" (UID: "bbf8d805-5576-4c5f-b548-a4a560c4a32d") I0513 02:01:04.509426 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "coredns-token-x9gx5" (UniqueName: "kubernetes.io/secret/bbf8d805-5576-4c5f-b548-a4a560c4a32d-coredns-token-x9gx5") pod "coredns-6c6bb68b64-2vmq5" (UID: "bbf8d805-5576-4c5f-b548-a4a560c4a32d") I0513 02:01:04.672449 flannel.go:92] Determining IP address of default interface I0513 02:01:04.672902 flannel.go:105] Using interface with name wlp2s0 and address 192.168.43.141 I0513 02:01:04.674851 kube.go:117] Waiting 10m0s for node controller to sync I0513 02:01:04.674906 kube.go:300] Starting kube subnet manager time="2020-05-13T02:01:04.682081843+02:00" level=info msg="labels have been set successfully on node: sos" I0513 02:01:04.696928 network_policy_controller.go:148] Starting network policy controller I0513 02:01:05.675312 kube.go:124] Node controller sync successful I0513 02:01:05.675525 vxlan.go:121] VXLAN config: VNI=1 Port=0 GBP=false Learning=false DirectRouting=false I0513 02:01:05.689666 flannel.go:78] Wrote subnet file to /run/flannel/subnet.env I0513 02:01:05.689689 flannel.go:82] Running backend. I0513 02:01:05.689698 vxlan_network.go:60] watching for new subnet leases I0513 02:02:34.402603 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "default-token-6d87q" (UniqueName: "kubernetes.io/secret/d273c5b3-cd2e-4d86-9475-1976bce2c46a-default-token-6d87q") pod "busybox-without-access" (UID: "d273c5b3-cd2e-4d86-9475-1976bce2c46a") I0513 02:02:41.125229 reconciler.go:183] operationExecutor.UnmountVolume started for volume "default-token-6d87q" (UniqueName: "kubernetes.io/secret/d273c5b3-cd2e-4d86-9475-1976bce2c46a-default-token-6d87q") pod "d273c5b3-cd2e-4d86-9475-1976bce2c46a" (UID: "d273c5b3-cd2e-4d86-9475-1976bce2c46a") I0513 02:02:41.127141 operation_generator.go:713] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/d273c5b3-cd2e-4d86-9475-1976bce2c46a-default-token-6d87q" (OuterVolumeSpecName: "default-token-6d87q") pod "d273c5b3-cd2e-4d86-9475-1976bce2c46a" (UID: "d273c5b3-cd2e-4d86-9475-1976bce2c46a"). InnerVo> I0513 02:02:41.225732 reconciler.go:303] Volume detached for volume "default-token-6d87q" (UniqueName: "kubernetes.io/secret/d273c5b3-cd2e-4d86-9475-1976bce2c46a-default-token-6d87q") on node "sos" DevicePath "" W0513 02:02:41.574591 manager.go:1131] Failed to process watch event {EventType:0 Name:/kubepods/besteffort/podd273c5b3-cd2e-4d86-9475-1976bce2c46a/f4c06c0d8ef0efa4b1041e6488142210f0d4e566557063a6b134cff06b9f4b42 WatchSource:0}: task f4c06c0d8ef0efa4b1041e6488142210f0d4e566557063a6b134cff06b9f4b42 not found: not fo> W0513 02:02:41.941923 pod_container_deletor.go:75] Container "44754e98f1e73ddfd5dfa00efd8a79552dad4508bfb1ef6bd9d87d7054eb188e" not found in pod's containers W0513 02:02:42.757004 kubelet_getters.go:297] Path "/var/lib/kubelet/pods/d273c5b3-cd2e-4d86-9475-1976bce2c46a/volumes" does not exist I0513 02:04:54.307279 reconciler.go:209] operationExecutor.VerifyControllerAttachedVolume started for volume "default-token-6d87q" (UniqueName: "kubernetes.io/secret/08811e5b-6e02-46f9-9951-38762d43388c-default-token-6d87q") pod "busybox-with-access" (UID: "08811e5b-6e02-46f9-9951-38762d43388c") E0513 02:05:09.346939 remote_runtime.go:128] StopPodSandbox "7c41bf6abd7e53c3b8dd163aa4ecf3a017a34c2b428bd69f67afbd6176501452" from runtime service failed: rpc error: code = Unknown desc = failed to destroy network for sandbox "7c41bf6abd7e53c3b8dd163aa4ecf3a017a34c2b428bd69f67afbd6176501452": failed to Statfs "/va> E0513 02:05:09.346999 kuberuntime_manager.go:898] Failed to stop sandbox {"containerd" "7c41bf6abd7e53c3b8dd163aa4ecf3a017a34c2b428bd69f67afbd6176501452"} E0513 02:05:09.347073 kuberuntime_manager.go:676] killPodWithSyncResult failed: failed to "KillPodSandbox" for "08811e5b-6e02-46f9-9951-38762d43388c" with KillPodSandboxError: "rpc error: code = Unknown desc = failed to destroy network for sandbox \"7c41bf6abd7e53c3b8dd163aa4ecf3a017a34c2b428bd69f67afbd6176501452\"> E0513 02:05:09.347153 pod_workers.go:191] Error syncing pod 08811e5b-6e02-46f9-9951-38762d43388c ("busybox-with-access_default(08811e5b-6e02-46f9-9951-38762d43388c)"), skipping: failed to "KillPodSandbox" for "08811e5b-6e02-46f9-9951-38762d43388c" with KillPodSandboxError: "rpc error: code = Unknown desc = failed t> I0513 02:05:09.453784 reconciler.go:183] operationExecutor.UnmountVolume started for volume "default-token-6d87q" (UniqueName: "kubernetes.io/secret/08811e5b-6e02-46f9-9951-38762d43388c-default-token-6d87q") pod "08811e5b-6e02-46f9-9951-38762d43388c" (UID: "08811e5b-6e02-46f9-9951-38762d43388c") I0513 02:05:09.459849 operation_generator.go:713] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/08811e5b-6e02-46f9-9951-38762d43388c-default-token-6d87q" (OuterVolumeSpecName: "default-token-6d87q") pod "08811e5b-6e02-46f9-9951-38762d43388c" (UID: "08811e5b-6e02-46f9-9951-38762d43388c"). InnerVo> I0513 02:05:09.554247 reconciler.go:303] Volume detached for volume "default-token-6d87q" (UniqueName: "kubernetes.io/secret/08811e5b-6e02-46f9-9951-38762d43388c-default-token-6d87q") on node "sos" DevicePath "" W0513 02:05:10.266958 pod_container_deletor.go:75] Container "7c41bf6abd7e53c3b8dd163aa4ecf3a017a34c2b428bd69f67afbd6176501452" not found in pod's containers W0513 02:05:10.765295 kubelet_getters.go:297] Path "/var/lib/kubelet/pods/08811e5b-6e02-46f9-9951-38762d43388c/volumes" does not exist ```
Output of: k3s kubectl get events ``` LAST SEEN TYPE REASON OBJECT MESSAGE 5m10s Normal Starting node/sos Starting kubelet. 5m10s Warning InvalidDiskCapacity node/sos invalid capacity 0 on image filesystem 5m10s Normal NodeHasSufficientMemory node/sos Node sos status is now: NodeHasSufficientMemory 5m10s Normal NodeHasNoDiskPressure node/sos Node sos status is now: NodeHasNoDiskPressure 5m10s Normal NodeHasSufficientPID node/sos Node sos status is now: NodeHasSufficientPID 5m10s Normal NodeAllocatableEnforced node/sos Updated Node Allocatable limit across pods 5m9s Normal Starting node/sos Starting kube-proxy. 4m59s Normal NodeReady node/sos Node sos status is now: NodeReady 4m59s Normal ScalingReplicaSet deployment/echoserver Scaled up replica set echoserver-5d8cc8d48 to 1 4m59s Normal SuccessfulCreate replicaset/echoserver-5d8cc8d48 Created pod: echoserver-5d8cc8d48-ckd5t Warning FailedScheduling pod/echoserver-5d8cc8d48-ckd5t 0/1 nodes are available: 1 node(s) had taints that the pod didn't tolerate. 4m59s Normal RegisteredNode node/sos Node sos event: Registered Node sos in Controller Normal Scheduled pod/echoserver-5d8cc8d48-ckd5t Successfully assigned default/echoserver-5d8cc8d48-ckd5t to sos 4m50s Normal Pulling pod/echoserver-5d8cc8d48-ckd5t Pulling image "gcr.io/google_containers/echoserver:1.10" 3m29s Normal Pulled pod/echoserver-5d8cc8d48-ckd5t Successfully pulled image "gcr.io/google_containers/echoserver:1.10" 3m29s Normal Created pod/echoserver-5d8cc8d48-ckd5t Created container echoserver 3m29s Normal Started pod/echoserver-5d8cc8d48-ckd5t Started container echoserver Normal Scheduled pod/busybox-without-access Successfully assigned default/busybox-without-access to sos 3m28s Normal Pulling pod/busybox-without-access Pulling image "busybox" 3m23s Normal Pulled pod/busybox-without-access Successfully pulled image "busybox" 3m22s Normal Created pod/busybox-without-access Created container busybox-without-access 3m22s Normal Started pod/busybox-without-access Started container busybox-without-access Normal Scheduled pod/busybox-with-access Successfully assigned default/busybox-with-access to sos 68s Normal Pulling pod/busybox-with-access Pulling image "busybox" 66s Normal Pulled pod/busybox-with-access Successfully pulled image "busybox" 66s Normal Created pod/busybox-with-access Created container busybox-with-access 66s Normal Started pod/busybox-with-access Started container busybox-with-access 53s Normal Killing pod/busybox-with-access Stopping container busybox-with-access ```
Output of: k3s kubectl logs deploy/echoserver ``` Generating self-signed cert Generating a 2048 bit RSA private key .......+++ ....................+++ writing new private key to '/certs/privateKey.key' ----- Starting nginx 10.42.0.4 - - [13/May/2020:00:02:40 +0000] "GET / HTTP/1.1" 200 434 "-" "Wget" 10.42.0.5 - - [13/May/2020:00:05:08 +0000] "GET / HTTP/1.1" 200 434 "-" "Wget" ```
erikwilson commented 4 years ago

We are using a an implementation called kube-router (https://github.com/cloudnativelabs/kube-router/blob/856c7d762a73df557e0a1d35721f48fe8ba7925d/pkg/controllers/netpol/network_policy_controller.go#L58) which includes a syncPeriod as part of it's operation, please feel free to open an issue there if it makes sense.

wilsonianb commented 4 years ago

Thanks. It looks like there's already a related issue: https://github.com/cloudnativelabs/kube-router/issues/873

wilsonianb commented 4 years ago

I just realized (even though it's mentioned in the kube-router issue I linked above) that this does not appear to be an issue with every network policy rule. For example, there does not appear to be a delay when an ingress rule restricts a new pod from connecting to another pod. (However, there may be a delay in the rule permitting a new pod to connect to another existing one.)

ShylajaDevadiga commented 3 years ago

Reproduced the issue in k3s version v1.17.4+k3s1

kubectl get networkpolicy
NAME              POD-SELECTOR   AGE
foo-deny-egress   app=foo        45s
/ # wget -qO- --timeout 1 http://web:80/
<!DOCTYPE html>
<html>
<head>
<title>Welcome to nginx!</title>
<style>

Validated on k3s v1.20.0-rc5+k3s1, there is no delay in policy enforcement. Labeled pod does not succeed after pod startup when deny egress traffic is applied

msmith93 commented 3 years ago

It looks like there is a --iptables-sync-period option on kube-router: https://www.kube-router.io/docs/user-guide/

If I'm understanding the description correctly, it sounds like changing this value could lower the amount of time it takes kube-router to enforce NetworkPolicy changes. Is it possible to make this option configurable in k3s?

brandond commented 3 years ago

Not at the moment. With recent updates to the network policy controller, the out of the box settings should be sufficient.

msmith93 commented 3 years ago

Thanks Brandon, I didn't catch the end of Shylaja's message above. I verified that there is no NetworkPolicy delay on k3d v4.3.0 with k3s v1.20.4-k3s1 👍

cpg314 commented 6 months ago

It seems like this is still happening on recent versions.

brandond commented 6 months ago

This is a limitation of network policies. Sync of policy rules is not instantaneous and does not block pod startup. Kubernetes is build around the concept of eventual consistency. Any component that has a dependency on the state of another component should be able to retry as necessary until that component becomes available - or reachable in this case.