Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Network policy enforcement is delayed #947

Closed
wilsonianb opened this issue Oct 23, 2019 · 11 comments
Closed

Network policy enforcement is delayed #947

wilsonianb opened this issue Oct 23, 2019 · 11 comments

Comments

@wilsonianb
Copy link

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
Copy link
Contributor

consideRatio commented May 12, 2020

@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
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} <nil> {{} [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 <nil> <nil> <nil> <nil> 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 <unknown>] [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
<unknown>   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
<unknown>   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
<unknown>   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
Copy link
Contributor

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} <nil> {{} [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 <nil> <nil> <nil> <nil> 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
<unknown>   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
<unknown>   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
<unknown>   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
<unknown>   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
Copy link
Contributor

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
Copy link
Author

Thanks.
It looks like there's already a related issue:
cloudnativelabs/kube-router#873

@wilsonianb
Copy link
Author

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
Copy link
Contributor

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

Development [DEPRECATED] automation moved this from To Test to Done Issue / Merged PR Dec 21, 2020
@msmith93
Copy link

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
Copy link
Contributor

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

@msmith93
Copy link

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
Copy link

cpg314 commented Apr 14, 2024

It seems like this is still happening on recent versions.

  • See the discussion at the end of [FEATURE] Install Opt-In NetworkPolicies  longhorn/longhorn#5403, which resulted in the longhorn developers writing

    Note: Depending on your CNI for cluster network, there might be some delay when Kubernetes applying network policies to the pod. This delay may fail Longhorn recurring job for taking Snapshot or Backup of the Volume since it cannot access longhorn-manager in the beginning. This is a known issue found in K3s with Traefik and is beyond Longhorn control.
    in their documentation.

  • I can reproduce the same issue in v1.28.5+k3s1 (5b2d127), installation with default settings, as follows:
    1. Create a NetworkPolicy that allows ingress only from kube-system and pods in the same namespace
    kind: NetworkPolicy
    apiVersion: networking.k8s.io/v1
    metadata:
      namespace: mynamespace
      name: deny-from-other-namespaces
    spec:
      podSelector:
        matchLabels:
      ingress:
      - from:
        - podSelector: {}
        - namespaceSelector:
            matchExpressions:
              - key: kubernetes.io/metadata.name
                operator: In
                values: ["kube-system"]
    
    1. In mynamespace, create a job that connects to another pod in the same namespace. The connection will be refused.
    2. Waiting briefly at the start of the job will make it succeed, as the policy has now been applied to that pod:
      initContainers:
        - name: sleep
          image: alpine:latest
          command: ["sleep", "5s"]
      

@k3s-io k3s-io locked and limited conversation to collaborators Apr 15, 2024
@brandond
Copy link
Contributor

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.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
No open projects
Development

No branches or pull requests

9 participants