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

k3s etcd panics after +10 hours on idle pi4 8GB cluster #2938

Closed
luckyluc74 opened this issue Feb 16, 2021 · 9 comments
Closed

k3s etcd panics after +10 hours on idle pi4 8GB cluster #2938

luckyluc74 opened this issue Feb 16, 2021 · 9 comments

Comments

@luckyluc74
Copy link

luckyluc74 commented Feb 16, 2021

Environmental Info:
K3s Version:
v1.20.2+k3s1 (1d4adb0) go version go1.15.5

Node(s) CPU architecture, OS, and Version:
Arm64 (raspberry pi 4 8GB), Ubuntu 20.10 with zfs

uname -a
Linux mnode1 5.8.0-1015-raspi #18-Ubuntu SMP PREEMPT Fri Feb 5 06:09:58 UTC 2021 aarch64 aarch64 aarch64 GNU/Linux

containerd version
containerd github.com/containerd/containerd 1.3.7-0ubuntu3.2

calico version
calico-3.17.2

zfs version
zfs-0.8.4-1ubuntu11.1
zfs-kmod-0.8.4-1ubuntu11.1

Cluster Configuration:
1 master

Describe the bug:
After installing basic k3s 1node cluster with calico and containerd after hours k3s panics and is turned into zombie process. Only a restart can kill k3s. The cluster is not doing anything besides running kubernetes dashboard. I have 3 identical pi 4 8GB running with same configuration both hard and software and already 2 out of 3 crashed. 1 after 16 hours and the other after around 25 hours

Steps To Reproduce:
install script used raspberry pi running ubuntu20.10

#!/bin/sh

set -e

# install k3s
curl -sfL https://get.k3s.io | INSTALL_K3S_CHANNEL=latest K3S_KUBECONFIG_MODE="644" INSTALL_K3S_EXEC="--flannel-backend=none --etcd-disable-snapshots --disable local-storage --disable metrics-server --disable-network-policy --disable traefik --disable-cloud-controller --cluster-init --snapshotter=zfs --container-runtime-endpoint unix:///run/containerd/containerd.sock" sh -

# install calico network
kubectl apply -f ~/work/calico-3.17.2.yaml

# needed for helm
export KUBECONFIG=/etc/rancher/k3s/k3s.yaml

# install kubernetes dahsboard
helm upgrade --install k8sdashboard k8s-dashboard/kubernetes-dashboard  --version 4.0.0  --create-namespace --namespace k8s-dashboard   --set service.type=LoadBalancer,service.externalPort=8432 -n k8s-dashboard

# add bashboard admin user
kubectl apply -f ~/work/dashboard.admin-user.yml
kubectl apply -f ~/work/dashboard.admin-user-role.yml


# export admin token
kubectl -n k8s-dashboard describe secret admin-user-token | grep ^token

Before running script I had containerd installed with following settings

install containerd

apt install containerd

add containerd config

mkdir /etc/containerd

add config /etc/containerd/config.toml

vi /etc/containerd/config.toml

add following

version = 2
[plugins."io.containerd.grpc.v1.cri".containerd]
  snapshotter = "zfs"
[plugins."io.containerd.internal.v1.opt"]
  path = "/var/lib/containerd/opt"

create containerd dataset

zfs create -o mountpoint=/var/lib/containerd/io.containerd.snapshotter.v1.zfs rpool/containerd

Expected behavior:
Just running stable and not crashing

Actual behavior:
k3s panics after +10 hours and leaves k3s process as a zombie process

Additional context / logs:

vcgencmd measure_temp
temp=33.6'C
vcgencmd get_throttled
throttled=0x0

bonnie++

bonnie++ -u root
Using uid:0, gid:0.
Writing a byte at a time...done
Writing intelligently...done
Rewriting...done
Reading a byte at a time...done
Reading intelligently...done
start 'em...done...done...done...done...done...
Create files in sequential order...done.
Stat files in sequential order...done.
Delete files in sequential order...done.
Create files in random order...done.
Stat files in random order...done.
Delete files in random order...done.
Version  1.98       ------Sequential Output------ --Sequential Input- --Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Name:Size etc        /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
mnode2       15720M   30k  97 61.4m  43 76.0m  67   76k  99  348m  99  7195 1369
Latency               282ms   36772us   25213us     122ms     492us   17940us
Version  1.98       ------Sequential Create------ --------Random Create--------
mnode2              -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16 -825176816  96 +++++ +++ -825176736   7 -825176696  95 +++++ +++ -825176616   4
Latency              9633us   30487us    3373ms    9379us     221us    5262ms

journalctl -b --no-pager -u k3s

mnode2
feb 16 12:42:25 mnode2 k3s[10737]: I0216 12:42:25.602914   10737 trace.go:205] Trace[1597683404]: "Get" url:/api/v1/namespaces/default,user-agent:k3s/v1.20.2+k3s1 (linux/arm64) kubernetes/1d4adb0,client:127.0.0.1 (16-Feb-2021 12:42:25.081) (total time: 521ms):
feb 16 12:42:25 mnode2 k3s[10737]: Trace[1597683404]: ---"About to write a response" 521ms (12:42:00.602)
feb 16 12:42:25 mnode2 k3s[10737]: Trace[1597683404]: [521.337994ms] [521.337994ms] END
feb 16 12:42:25 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:25.742+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"107.699992ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/configmaps/kube-system/k3s\" ","response":"range_response_count:1 size:499"}
feb 16 12:42:25 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:42:25.743+0100","caller":"traceutil/trace.go:145","msg":"trace[224862086] range","detail":"{range_begin:/registry/configmaps/kube-system/k3s; range_end:; response_count:1; response_revision:90055; }","duration":"108.300539ms","start":"2021-02-16T12:42:25.634+0100","end":"2021-02-16T12:42:25.742+0100","steps":["trace[224862086] 'agreement among raft nodes before linearized reading'  (duration: 107.53144ms)"]}
feb 16 12:42:26 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:26.417+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"635.944256ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/certificatesigningrequests/\" range_end:\"/registry/certificatesigningrequests0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 12:42:26 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:42:26.417+0100","caller":"traceutil/trace.go:145","msg":"trace[708196213] range","detail":"{range_begin:/registry/certificatesigningrequests/; range_end:/registry/certificatesigningrequests0; response_count:0; response_revision:90056; }","duration":"636.250345ms","start":"2021-02-16T12:42:25.781+0100","end":"2021-02-16T12:42:26.417+0100","steps":["trace[708196213] 'agreement among raft nodes before linearized reading'  (duration: 290.848452ms)","trace[708196213] 'range keys from in-memory index tree'  (duration: 345.028694ms)"]}
feb 16 12:42:26 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:26.417+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"223.370017ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:474"}
feb 16 12:42:26 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:42:26.418+0100","caller":"traceutil/trace.go:145","msg":"trace[1816472039] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:90056; }","duration":"224.429687ms","start":"2021-02-16T12:42:26.193+0100","end":"2021-02-16T12:42:26.418+0100","steps":["trace[1816472039] 'range keys from in-memory index tree'  (duration: 223.180983ms)"]}
feb 16 12:42:30 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:30.611+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"211.70693ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/crd.projectcalico.org/ipamhandles/\" range_end:\"/registry/crd.projectcalico.org/ipamhandles0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 12:42:30 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:42:30.611+0100","caller":"traceutil/trace.go:145","msg":"trace[1721193044] range","detail":"{range_begin:/registry/crd.projectcalico.org/ipamhandles/; range_end:/registry/crd.projectcalico.org/ipamhandles0; response_count:0; response_revision:90062; }","duration":"212.100757ms","start":"2021-02-16T12:42:30.399+0100","end":"2021-02-16T12:42:30.611+0100","steps":["trace[1721193044] 'agreement among raft nodes before linearized reading'  (duration: 35.715216ms)","trace[1721193044] 'range keys from in-memory index tree'  (duration: 175.79892ms)"]}
feb 16 12:42:35 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:35.358+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"275.181832ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/namespaces/default\" ","response":"range_response_count:1 size:245"}
feb 16 12:42:35 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:35.358+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"440.41039ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-controller-manager\" ","response":"range_response_count:1 size:493"}
feb 16 12:42:35 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:42:35.358+0100","caller":"traceutil/trace.go:145","msg":"trace[1014185141] range","detail":"{range_begin:/registry/leases/kube-system/kube-controller-manager; range_end:; response_count:1; response_revision:90070; }","duration":"440.848198ms","start":"2021-02-16T12:42:34.917+0100","end":"2021-02-16T12:42:35.358+0100","steps":["trace[1014185141] 'range keys from in-memory index tree'  (duration: 439.979063ms)"]}
feb 16 12:42:35 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:42:35.358+0100","caller":"traceutil/trace.go:145","msg":"trace[1445956367] range","detail":"{range_begin:/registry/namespaces/default; range_end:; response_count:1; response_revision:90070; }","duration":"275.467755ms","start":"2021-02-16T12:42:35.083+0100","end":"2021-02-16T12:42:35.358+0100","steps":["trace[1445956367] 'range keys from in-memory index tree'  (duration: 274.764895ms)"]}
feb 16 12:42:36 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:36.057+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"454.461499ms","expected-duration":"100ms","prefix":"","request":"header:<ID:5198129955925073333 username:\"etcd-client\" auth_revision:1 > txn:<compare:<target:MOD key:\"/registry/masterleases/192.168.111.34\" mod_revision:90055 > success:<request_put:<key:\"/registry/masterleases/192.168.111.34\" value_size:70 lease:5198129955925073331 >> failure:<request_range:<key:\"/registry/masterleases/192.168.111.34\" > >>","response":"size:18"}
feb 16 12:42:36 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:36.059+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"189.597736ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/configmaps/kube-system/k3s\" ","response":"range_response_count:1 size:499"}
feb 16 12:42:36 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:42:36.059+0100","caller":"traceutil/trace.go:145","msg":"trace[1594548493] range","detail":"{range_begin:/registry/configmaps/kube-system/k3s; range_end:; response_count:1; response_revision:90072; }","duration":"189.850622ms","start":"2021-02-16T12:42:35.869+0100","end":"2021-02-16T12:42:36.059+0100","steps":["trace[1594548493] 'agreement among raft nodes before linearized reading'  (duration: 189.102429ms)"]}
feb 16 12:42:36 mnode2 k3s[10737]: I0216 12:42:36.063809   10737 trace.go:205] Trace[1874996068]: "GuaranteedUpdate etcd3" type:*v1.Endpoints (16-Feb-2021 12:42:35.376) (total time: 687ms):
feb 16 12:42:36 mnode2 k3s[10737]: Trace[1874996068]: ---"Transaction committed" 682ms (12:42:00.063)
feb 16 12:42:36 mnode2 k3s[10737]: Trace[1874996068]: [687.415377ms] [687.415377ms] END
feb 16 12:42:36 mnode2 k3s[10737]: I0216 12:42:36.070740   10737 trace.go:205] Trace[1420648311]: "GuaranteedUpdate etcd3" type:*coordination.Lease (16-Feb-2021 12:42:35.380) (total time: 689ms):
feb 16 12:42:36 mnode2 k3s[10737]: Trace[1420648311]: ---"Transaction committed" 688ms (12:42:00.070)
feb 16 12:42:36 mnode2 k3s[10737]: Trace[1420648311]: [689.829268ms] [689.829268ms] END
feb 16 12:42:36 mnode2 k3s[10737]: I0216 12:42:36.071183   10737 trace.go:205] Trace[421139630]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-controller-manager,user-agent:k3s/v1.20.2+k3s1 (linux/arm64) kubernetes/1d4adb0/leader-election,client:127.0.0.1 (16-Feb-2021 12:42:35.380) (total time: 690ms):
feb 16 12:42:36 mnode2 k3s[10737]: Trace[421139630]: ---"Object stored in database" 690ms (12:42:00.070)
feb 16 12:42:36 mnode2 k3s[10737]: Trace[421139630]: [690.527258ms] [690.527258ms] END
feb 16 12:42:41 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:41.346+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"449.325613ms","expected-duration":"100ms","prefix":"","request":"header:<ID:5198129955925073361 > lease_revoke:<id:482377a76f3b1d7c>","response":"size:30"}
feb 16 12:42:45 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:45.335+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"251.207113ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/namespaces/default\" ","response":"range_response_count:1 size:245"}
feb 16 12:42:45 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:42:45.335+0100","caller":"traceutil/trace.go:145","msg":"trace[735758922] range","detail":"{range_begin:/registry/namespaces/default; range_end:; response_count:1; response_revision:90087; }","duration":"251.534053ms","start":"2021-02-16T12:42:45.084+0100","end":"2021-02-16T12:42:45.335+0100","steps":["trace[735758922] 'range keys from in-memory index tree'  (duration: 250.945598ms)"]}
feb 16 12:42:45 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:45.765+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"224.598836ms","expected-duration":"100ms","prefix":"","request":"header:<ID:5198129955925073387 username:\"etcd-client\" auth_revision:1 > txn:<compare:<target:MOD key:\"/registry/masterleases/192.168.111.34\" mod_revision:90071 > success:<request_put:<key:\"/registry/masterleases/192.168.111.34\" value_size:70 lease:5198129955925073385 >> failure:<request_range:<key:\"/registry/masterleases/192.168.111.34\" > >>","response":"size:18"}
feb 16 12:42:50 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:50.686+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"194.032748ms","expected-duration":"100ms","prefix":"","request":"header:<ID:5198129955925073409 > lease_revoke:<id:482377a76f3b1db3>","response":"size:30"}
feb 16 12:42:50 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:42:50.687+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"230.152626ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-controller-manager\" ","response":"range_response_count:1 size:493"}
feb 16 12:42:50 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:42:50.687+0100","caller":"traceutil/trace.go:145","msg":"trace[118880787] range","detail":"{range_begin:/registry/leases/kube-system/kube-controller-manager; range_end:; response_count:1; response_revision:90095; }","duration":"230.31042ms","start":"2021-02-16T12:42:50.456+0100","end":"2021-02-16T12:42:50.687+0100","steps":["trace[118880787] 'agreement among raft nodes before linearized reading'  (duration: 229.923371ms)"]}
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.307248   10737 sysinfo.go:203] Nodes topology is not available, providing CPU topology
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.308057   10737 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu0/online: open /sys/devices/system/cpu/cpu0/online: no such file or directory
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.308148   10737 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu1/online: open /sys/devices/system/cpu/cpu1/online: no such file or directory
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.308224   10737 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu2/online: open /sys/devices/system/cpu/cpu2/online: no such file or directory
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.308292   10737 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu3/online: open /sys/devices/system/cpu/cpu3/online: no such file or directory
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.308910   10737 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu0 online state, skipping
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.308980   10737 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu1 online state, skipping
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.309038   10737 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu2 online state, skipping
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.309091   10737 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu3 online state, skipping
feb 16 12:44:22 mnode2 k3s[10737]: E0216 12:44:22.309110   10737 machine.go:72] Cannot read number of physical cores correctly, number of cores set to 0
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.309407   10737 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu0 online state, skipping
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.309466   10737 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu1 online state, skipping
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.309516   10737 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu2 online state, skipping
feb 16 12:44:22 mnode2 k3s[10737]: W0216 12:44:22.309563   10737 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu3 online state, skipping
feb 16 12:44:22 mnode2 k3s[10737]: E0216 12:44:22.309582   10737 machine.go:86] Cannot read number of sockets correctly, number of sockets set to 0
feb 16 12:44:31 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:44:31.135+0100","caller":"mvcc/index.go:189","msg":"compact tree index","revision":89767}
feb 16 12:44:31 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:44:31.139+0100","caller":"mvcc/kvstore_compaction.go:56","msg":"finished scheduled compaction","compact-revision":89767,"took":"2.681776ms"}
feb 16 12:45:45 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:45:45.709+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"369.24699ms","expected-duration":"100ms","prefix":"","request":"header:<ID:5198129955925074368 username:\"etcd-client\" auth_revision:1 > txn:<compare:<target:MOD key:\"/registry/leases/kube-system/kube-scheduler\" mod_revision:90384 > success:<request_put:<key:\"/registry/leases/kube-system/kube-scheduler\" value_size:404 >> failure:<request_range:<key:\"/registry/leases/kube-system/kube-scheduler\" > >>","response":"size:18"}
feb 16 12:45:45 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:45:45.709+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"595.324688ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/masterleases/192.168.111.34\" ","response":"range_response_count:1 size:143"}
feb 16 12:45:45 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:45:45.709+0100","caller":"traceutil/trace.go:145","msg":"trace[1934758011] range","detail":"{range_begin:/registry/masterleases/192.168.111.34; range_end:; response_count:1; response_revision:90386; }","duration":"595.795626ms","start":"2021-02-16T12:45:45.114+0100","end":"2021-02-16T12:45:45.709+0100","steps":["trace[1934758011] 'agreement among raft nodes before linearized reading'  (duration: 225.661056ms)","trace[1934758011] 'range keys from in-memory index tree'  (duration: 369.249027ms)"]}
feb 16 12:45:45 mnode2 k3s[10737]: I0216 12:45:45.716334   10737 trace.go:205] Trace[1427731587]: "GuaranteedUpdate etcd3" type:*coordination.Lease (16-Feb-2021 12:45:45.117) (total time: 598ms):
feb 16 12:45:45 mnode2 k3s[10737]: Trace[1427731587]: ---"Transaction committed" 597ms (12:45:00.716)
feb 16 12:45:45 mnode2 k3s[10737]: Trace[1427731587]: [598.444847ms] [598.444847ms] END
feb 16 12:45:45 mnode2 k3s[10737]: I0216 12:45:45.716846   10737 trace.go:205] Trace[1373749842]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-scheduler,user-agent:k3s/v1.20.2+k3s1 (linux/arm64) kubernetes/1d4adb0/leader-election,client:127.0.0.1 (16-Feb-2021 12:45:45.117) (total time: 599ms):
feb 16 12:45:45 mnode2 k3s[10737]: Trace[1373749842]: ---"Object stored in database" 598ms (12:45:00.716)
feb 16 12:45:45 mnode2 k3s[10737]: Trace[1373749842]: [599.16704ms] [599.16704ms] END
feb 16 12:45:45 mnode2 k3s[10737]: I0216 12:45:45.717219   10737 trace.go:205] Trace[478338283]: "GuaranteedUpdate etcd3" type:*coordination.Lease (16-Feb-2021 12:45:45.117) (total time: 599ms):
feb 16 12:45:45 mnode2 k3s[10737]: Trace[478338283]: ---"Transaction committed" 598ms (12:45:00.717)
feb 16 12:45:45 mnode2 k3s[10737]: Trace[478338283]: [599.356852ms] [599.356852ms] END
feb 16 12:45:45 mnode2 k3s[10737]: I0216 12:45:45.717678   10737 trace.go:205] Trace[821038377]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-controller-manager,user-agent:k3s/v1.20.2+k3s1 (linux/arm64) kubernetes/1d4adb0/leader-election,client:127.0.0.1 (16-Feb-2021 12:45:45.117) (total time: 600ms):
feb 16 12:45:45 mnode2 k3s[10737]: Trace[821038377]: ---"Object stored in database" 599ms (12:45:00.717)
feb 16 12:45:45 mnode2 k3s[10737]: Trace[821038377]: [600.04862ms] [600.04862ms] END
feb 16 12:45:46 mnode2 k3s[10737]: I0216 12:45:46.083934   10737 trace.go:205] Trace[1330935270]: "GuaranteedUpdate etcd3" type:*v1.Endpoints (16-Feb-2021 12:45:45.113) (total time: 970ms):
feb 16 12:45:46 mnode2 k3s[10737]: Trace[1330935270]: ---"initial value restored" 602ms (12:45:00.715)
feb 16 12:45:46 mnode2 k3s[10737]: Trace[1330935270]: ---"Transaction committed" 362ms (12:45:00.083)
feb 16 12:45:46 mnode2 k3s[10737]: Trace[1330935270]: [970.513537ms] [970.513537ms] END
feb 16 12:45:47 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:45:47.948+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"102.774415ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/crd.projectcalico.org/felixconfigurations/\" range_end:\"/registry/crd.projectcalico.org/felixconfigurations0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 12:45:47 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:45:47.948+0100","caller":"traceutil/trace.go:145","msg":"trace[409419682] range","detail":"{range_begin:/registry/crd.projectcalico.org/felixconfigurations/; range_end:/registry/crd.projectcalico.org/felixconfigurations0; response_count:0; response_revision:90392; }","duration":"102.980671ms","start":"2021-02-16T12:45:47.845+0100","end":"2021-02-16T12:45:47.948+0100","steps":["trace[409419682] 'agreement among raft nodes before linearized reading'  (duration: 102.625361ms)"]}
feb 16 12:45:49 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:45:49.728+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"469.729903ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"range_response_count:0 size:6"}
feb 16 12:45:49 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:45:49.729+0100","caller":"traceutil/trace.go:145","msg":"trace[1714003123] range","detail":"{range_begin:/registry/health; range_end:; response_count:0; response_revision:90393; }","duration":"469.996362ms","start":"2021-02-16T12:45:49.258+0100","end":"2021-02-16T12:45:49.728+0100","steps":["trace[1714003123] 'agreement among raft nodes before linearized reading'  (duration: 196.497203ms)","trace[1714003123] 'range keys from in-memory index tree'  (duration: 273.159905ms)"]}
feb 16 12:45:49 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:45:49.729+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"273.405679ms","expected-duration":"100ms","prefix":"","request":"header:<ID:5198129955925074390 username:\"etcd-client\" auth_revision:1 > txn:<compare:<target:MOD key:\"/registry/configmaps/kube-system/k3s\" mod_revision:90390 > success:<request_put:<key:\"/registry/configmaps/kube-system/k3s\" value_size:436 >> failure:<request_range:<key:\"/registry/configmaps/kube-system/k3s\" > >>","response":"size:18"}
feb 16 12:45:49 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:45:49.729+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"458.485621ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/cronjobs/\" range_end:\"/registry/cronjobs0\" limit:500 ","response":"range_response_count:0 size:6"}
feb 16 12:45:49 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:45:49.729+0100","caller":"traceutil/trace.go:145","msg":"trace[480231716] range","detail":"{range_begin:/registry/cronjobs/; range_end:/registry/cronjobs0; response_count:0; response_revision:90394; }","duration":"458.640267ms","start":"2021-02-16T12:45:49.271+0100","end":"2021-02-16T12:45:49.729+0100","steps":["trace[480231716] 'agreement among raft nodes before linearized reading'  (duration: 458.317364ms)"]}
feb 16 12:45:49 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:45:49.732+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"284.105671ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/mutatingwebhookconfigurations/\" range_end:\"/registry/mutatingwebhookconfigurations0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 12:45:49 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:45:49.732+0100","caller":"traceutil/trace.go:145","msg":"trace[1567203758] range","detail":"{range_begin:/registry/mutatingwebhookconfigurations/; range_end:/registry/mutatingwebhookconfigurations0; response_count:0; response_revision:90394; }","duration":"284.291298ms","start":"2021-02-16T12:45:49.448+0100","end":"2021-02-16T12:45:49.732+0100","steps":["trace[1567203758] 'agreement among raft nodes before linearized reading'  (duration: 283.917119ms)"]}
feb 16 12:45:50 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:45:50.488+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"601.129236ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/\" range_end:\"/registry/leases0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 12:45:50 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:45:50.488+0100","caller":"traceutil/trace.go:145","msg":"trace[838556129] range","detail":"{range_begin:/registry/leases/; range_end:/registry/leases0; response_count:0; response_revision:90395; }","duration":"601.406398ms","start":"2021-02-16T12:45:49.887+0100","end":"2021-02-16T12:45:50.488+0100","steps":["trace[838556129] 'agreement among raft nodes before linearized reading'  (duration: 247.595998ms)","trace[838556129] 'range keys from in-memory index tree'  (duration: 353.464887ms)"]}
feb 16 12:45:50 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:45:50.488+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"523.964264ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-controller-manager\" ","response":"range_response_count:1 size:493"}
feb 16 12:45:50 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:45:50.489+0100","caller":"traceutil/trace.go:145","msg":"trace[473477386] range","detail":"{range_begin:/registry/leases/kube-system/kube-controller-manager; range_end:; response_count:1; response_revision:90395; }","duration":"524.427479ms","start":"2021-02-16T12:45:49.964+0100","end":"2021-02-16T12:45:50.489+0100","steps":["trace[473477386] 'agreement among raft nodes before linearized reading'  (duration: 170.432155ms)","trace[473477386] 'range keys from in-memory index tree'  (duration: 353.446572ms)"]}
feb 16 12:45:50 mnode2 k3s[10737]: I0216 12:45:50.492165   10737 trace.go:205] Trace[1567789580]: "Get" url:/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-controller-manager,user-agent:k3s/v1.20.2+k3s1 (linux/arm64) kubernetes/1d4adb0/leader-election,client:127.0.0.1 (16-Feb-2021 12:45:49.963) (total time: 528ms):
feb 16 12:45:50 mnode2 k3s[10737]: Trace[1567789580]: ---"About to write a response" 528ms (12:45:00.491)
feb 16 12:45:50 mnode2 k3s[10737]: Trace[1567789580]: [528.881674ms] [528.881674ms] END
feb 16 12:45:55 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:45:55.474+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"386.787608ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/namespaces/default\" ","response":"range_response_count:1 size:245"}
feb 16 12:45:55 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:45:55.475+0100","caller":"traceutil/trace.go:145","msg":"trace[793832486] range","detail":"{range_begin:/registry/namespaces/default; range_end:; response_count:1; response_revision:90402; }","duration":"387.079919ms","start":"2021-02-16T12:45:55.087+0100","end":"2021-02-16T12:45:55.474+0100","steps":["trace[793832486] 'agreement among raft nodes before linearized reading'  (duration: 153.172536ms)","trace[793832486] 'range keys from in-memory index tree'  (duration: 233.47924ms)"]}
feb 16 12:45:55 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:45:55.789+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"109.592169ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/crd.projectcalico.org/networkpolicies/\" range_end:\"/registry/crd.projectcalico.org/networkpolicies0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 12:45:55 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:45:55.789+0100","caller":"traceutil/trace.go:145","msg":"trace[621170976] range","detail":"{range_begin:/registry/crd.projectcalico.org/networkpolicies/; range_end:/registry/crd.projectcalico.org/networkpolicies0; response_count:0; response_revision:90403; }","duration":"109.816184ms","start":"2021-02-16T12:45:55.679+0100","end":"2021-02-16T12:45:55.789+0100","steps":["trace[621170976] 'range keys from in-memory index tree'  (duration: 109.367913ms)"]}
feb 16 12:46:00 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:46:00.109+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"365.935097ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/jobs/\" range_end:\"/registry/jobs0\" limit:500 ","response":"range_response_count:0 size:6"}
feb 16 12:46:00 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:46:00.113+0100","caller":"traceutil/trace.go:145","msg":"trace[1938677979] range","detail":"{range_begin:/registry/jobs/; range_end:/registry/jobs0; response_count:0; response_revision:90410; }","duration":"370.215683ms","start":"2021-02-16T12:45:59.743+0100","end":"2021-02-16T12:46:00.113+0100","steps":["trace[1938677979] 'agreement among raft nodes before linearized reading'  (duration: 55.185865ms)","trace[1938677979] 'range keys from in-memory index tree'  (duration: 310.697972ms)"]}
feb 16 12:46:00 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:46:00.109+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"269.407127ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/configmaps/kube-system/k3s\" ","response":"range_response_count:1 size:499"}
feb 16 12:46:00 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:46:00.120+0100","caller":"traceutil/trace.go:145","msg":"trace[1038467145] range","detail":"{range_begin:/registry/configmaps/kube-system/k3s; range_end:; response_count:1; response_revision:90410; }","duration":"280.969034ms","start":"2021-02-16T12:45:59.839+0100","end":"2021-02-16T12:46:00.120+0100","steps":["trace[1038467145] 'range keys from in-memory index tree'  (duration: 269.080262ms)"]}
feb 16 12:46:00 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:46:00.109+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"366.402609ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/crd.projectcalico.org/clusterinformations/default\" ","response":"range_response_count:1 size:913"}
feb 16 12:46:00 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:46:00.121+0100","caller":"traceutil/trace.go:145","msg":"trace[1811205618] range","detail":"{range_begin:/registry/crd.projectcalico.org/clusterinformations/default; range_end:; response_count:1; response_revision:90410; }","duration":"378.816947ms","start":"2021-02-16T12:45:59.742+0100","end":"2021-02-16T12:46:00.121+0100","steps":["trace[1811205618] 'agreement among raft nodes before linearized reading'  (duration: 55.367474ms)","trace[1811205618] 'range keys from in-memory index tree'  (duration: 310.783009ms)"]}
feb 16 12:46:00 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:46:00.475+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"346.748968ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/cronjobs/\" range_end:\"/registry/cronjobs0\" limit:500 ","response":"range_response_count:0 size:6"}
feb 16 12:46:00 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:46:00.476+0100","caller":"traceutil/trace.go:145","msg":"trace[635858053] range","detail":"{range_begin:/registry/cronjobs/; range_end:/registry/cronjobs0; response_count:0; response_revision:90411; }","duration":"347.06189ms","start":"2021-02-16T12:46:00.128+0100","end":"2021-02-16T12:46:00.475+0100","steps":["trace[635858053] 'agreement among raft nodes before linearized reading'  (duration: 266.155508ms)","trace[635858053] 'range keys from in-memory index tree'  (duration: 80.506702ms)"]}
feb 16 12:46:05 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:46:05.569+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"300.60599ms","expected-duration":"100ms","prefix":"","request":"header:<ID:5198129955925074478 username:\"etcd-client\" auth_revision:1 > txn:<compare:<target:MOD key:\"/registry/masterleases/192.168.111.34\" mod_revision:90403 > success:<request_put:<key:\"/registry/masterleases/192.168.111.34\" value_size:70 lease:5198129955925074476 >> failure:<request_range:<key:\"/registry/masterleases/192.168.111.34\" > >>","response":"size:18"}
feb 16 12:46:05 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:46:05.570+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"455.468503ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-controller-manager\" ","response":"range_response_count:1 size:492"}
feb 16 12:46:05 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:46:05.570+0100","caller":"traceutil/trace.go:145","msg":"trace[2088913245] range","detail":"{range_begin:/registry/leases/kube-system/kube-controller-manager; range_end:; response_count:1; response_revision:90419; }","duration":"455.718037ms","start":"2021-02-16T12:46:05.115+0100","end":"2021-02-16T12:46:05.570+0100","steps":["trace[2088913245] 'agreement among raft nodes before linearized reading'  (duration: 455.030528ms)"]}
feb 16 12:46:06 mnode2 k3s[10737]: {"level":"warn","ts":"2021-02-16T12:46:06.693+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"130.500736ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/storageclasses/\" range_end:\"/registry/storageclasses0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 12:46:06 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:46:06.696+0100","caller":"traceutil/trace.go:145","msg":"trace[306188567] range","detail":"{range_begin:/registry/storageclasses/; range_end:/registry/storageclasses0; response_count:0; response_revision:90422; }","duration":"133.157068ms","start":"2021-02-16T12:46:06.563+0100","end":"2021-02-16T12:46:06.696+0100","steps":["trace[306188567] 'range keys from in-memory index tree'  (duration: 130.295443ms)"]}
feb 16 12:46:20 mnode2 k3s[10737]: E0216 12:46:20.142784   10737 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
feb 16 12:46:20 mnode2 k3s[10737]: I0216 12:46:20.147102   10737 trace.go:205] Trace[873651971]: "Get" url:/apis/crd.projectcalico.org/v1/clusterinformations/default,user-agent:Go-http-client/1.1,client:172.16.102.67 (16-Feb-2021 12:46:10.149) (total time: 9997ms):
feb 16 12:46:20 mnode2 k3s[10737]: Trace[873651971]: [9.997222741s] [9.997222741s] END
feb 16 12:46:20 mnode2 k3s[10737]: E0216 12:46:20.287834   10737 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
feb 16 12:46:20 mnode2 k3s[10737]: E0216 12:46:20.287834   10737 leaderelection.go:325] error retrieving resource lock kube-system/kube-scheduler: Get "https://127.0.0.1:6444/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-scheduler?timeout=10s": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
feb 16 12:46:20 mnode2 k3s[10737]: I0216 12:46:20.288875   10737 leaderelection.go:278] failed to renew lease kube-system/kube-scheduler: timed out waiting for the condition
feb 16 12:46:20 mnode2 k3s[10737]: I0216 12:46:20.288879   10737 trace.go:205] Trace[532990064]: "Get" url:/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-scheduler,user-agent:k3s/v1.20.2+k3s1 (linux/arm64) kubernetes/1d4adb0/leader-election,client:127.0.0.1 (16-Feb-2021 12:46:10.299) (total time: 9989ms):
feb 16 12:46:20 mnode2 k3s[10737]: Trace[532990064]: [9.989502206s] [9.989502206s] END
feb 16 12:46:20 mnode2 k3s[10737]: F0216 12:46:20.289715   10737 server.go:205] leaderelection lost
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 4829 [running]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/klog/v2.stacks(0x4000132001, 0x400e005c20, 0x41, 0x81)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:1026 +0xac
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/klog/v2.(*loggingT).output(0x6739880, 0x4000000003, 0x0, 0x0, 0x4007a7d500, 0x63b9faf, 0x9, 0xcd, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:975 +0x168
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/klog/v2.(*loggingT).printf(0x6739880, 0x3, 0x0, 0x0, 0x0, 0x0, 0x3cdc8d5, 0x13, 0x0, 0x0, ...)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:750 +0x12c
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/klog/v2.Fatalf(...)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:1502
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app.Run.func3()
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:205 +0x90
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/client-go/tools/leaderelection.(*LeaderElector).Run.func1(0x400db08b40)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/client-go/tools/leaderelection/leaderelection.go:199 +0x2c
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/client-go/tools/leaderelection.(*LeaderElector).Run(0x400db08b40, 0x444d740, 0x4009a8e580)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/client-go/tools/leaderelection/leaderelection.go:209 +0x130
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app.Run(0x444d740, 0x4007866d40, 0x40075ec570, 0x4012025200, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:213 +0x470
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app.runCommand(0x40075e9600, 0x4009202820, 0x0, 0x0, 0x0, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:132 +0x104
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app.NewSchedulerCommand.func1(0x40075e9600, 0x4010406840, 0x0, 0x6)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:81 +0x48
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/spf13/cobra.(*Command).execute(0x40075e9600, 0x40094b1500, 0x6, 0x8, 0x40075e9600, 0x40094b1500)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/spf13/cobra/command.go:854 +0x1c4
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0x40075e9600, 0x0, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/spf13/cobra/command.go:958 +0x268
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/spf13/cobra.(*Command).Execute(...)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/spf13/cobra/command.go:895
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/pkg/daemons/executor.Embedded.Scheduler.func1(0x4005082120, 0x40075e9600)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/daemons/executor/embed.go:67 +0x38
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/pkg/daemons/executor.Embedded.Scheduler
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/daemons/executor/embed.go:65 +0x7c
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 1 [chan receive, 902 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/pkg/agent.run(0x444d740, 0x40014d7500, 0x400aa8a690, 0x6a, 0x0, 0x0, 0x0, 0x0, 0x40097d96c0, 0x16, ...)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/agent/run.go:121 +0x1c4
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/pkg/agent.Run(0x444d740, 0x40014d7500, 0x400aa8a690, 0x6a, 0x0, 0x0, 0x0, 0x0, 0x40097d96c0, 0x16, ...)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/agent/run.go:172 +0x2fc
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/pkg/cli/server.run(0x400129cb00, 0x673a740, 0x4001492e78, 0x48)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/cli/server/server.go:283 +0x123c
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/pkg/cli/server.Run(0x400129cb00, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/cli/server/server.go:38 +0x58
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/urfave/cli.HandleAction(0x35694c0, 0x3eb7160, 0x400129cb00, 0x400129cb00, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/urfave/cli/app.go:523 +0x118
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/urfave/cli.Command.Run(0x3caf617, 0x6, 0x0, 0x0, 0x0, 0x0, 0x0, 0x3ce3b73, 0x15, 0x40014ca1e0, ...)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/urfave/cli/command.go:174 +0x41c
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/urfave/cli.(*App).Run(0x40011dbc00, 0x4000136800, 0x10, 0x10, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/urfave/cli/app.go:276 +0x584
feb 16 12:46:21 mnode2 k3s[10737]: main.main()
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/cmd/server/main.go:47 +0x4d8
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 19 [chan receive]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/klog/v2.(*loggingT).flushDaemon(0x6739880)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:1169 +0x70
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/k8s.io/klog/v2.init.0
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:417 +0x124
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 21 [chan receive]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/klog.(*loggingT).flushDaemon(0x67395c0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/klog.go:1010 +0x70
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/k8s.io/klog.init.0
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/klog.go:411 +0x118
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 101 [sleep]:
feb 16 12:46:21 mnode2 k3s[10737]: time.Sleep(0x3b9aca00)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/runtime/time.go:188 +0xc0
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/kubernetes/pkg/scheduler/framework/runtime.(*metricsRecorder).run(0x4000a625d0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/pkg/scheduler/framework/runtime/metrics_recorder.go:88 +0x3c
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/k8s.io/kubernetes/pkg/scheduler/framework/runtime.newMetricsRecorder
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/pkg/scheduler/framework/runtime/metrics_recorder.go:60 +0xf0
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 185 [syscall, 902 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: os/signal.signal_recv(0x4000db2720)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/runtime/sigqueue.go:147 +0xc4
feb 16 12:46:21 mnode2 k3s[10737]: os/signal.loop()
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/os/signal/signal_unix.go:23 +0x20
feb 16 12:46:21 mnode2 k3s[10737]: created by os/signal.Notify.func1.1
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/os/signal/signal.go:150 +0x44
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 172 [chan receive]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop(0x4000a86900)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:173 +0x2d0
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.NewMergeLogger
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:91 +0x7c
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 133 [chan receive]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop(0x40003fece0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:173 +0x2d0
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.NewMergeLogger
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:91 +0x7c
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 169 [chan receive]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop(0x4000a86700)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:173 +0x2d0
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.NewMergeLogger
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:91 +0x7c
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 129 [chan receive, 902 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/signals.SetupSignalHandler.func1(0x40014ce7e0, 0x4000c054b0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/signals/signal.go:37 +0x2c
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/signals.SetupSignalHandler
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/signals/signal.go:36 +0xdc
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 12652 [sync.Cond.Wait, 898 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: runtime.goparkunlock(...)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/runtime/proc.go:312
feb 16 12:46:21 mnode2 k3s[10737]: sync.runtime_notifyListWait(0x40102d53d0, 0x6)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/runtime/sema.go:513 +0xfc
feb 16 12:46:21 mnode2 k3s[10737]: sync.(*Cond).Wait(0x40102d53c0)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/sync/cond.go:56 +0xb0
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/client-go/util/workqueue.(*Type).Get(0x4011eb0ea0, 0x0, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/client-go/util/workqueue/queue.go:145 +0x84
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/generic.(*Controller).processNextWorkItem(0x400880cd20, 0x40116fa601)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/generic/controller.go:127 +0x34
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/generic.(*Controller).runWorker(0x400880cd20)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/generic/controller.go:122 +0x28
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x4011687be0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:155 +0x64
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x4011687be0, 0x4393080, 0x4010678d80, 0x642f23223a226601, 0x4000fb3140)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:156 +0x74
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x4011687be0, 0x3b9aca00, 0x0, 0x1, 0x4000fb3140)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:133 +0x88
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/wait.Until(0x4011687be0, 0x3b9aca00, 0x4000fb3140)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:90 +0x48
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/generic.(*Controller).run
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/generic/controller.go:104 +0x124
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 227 [select, 182 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener.(*listener).WrapExpiration.func1(0x4001562420, 0x5a, 0x444d740, 0x400154a9c0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener/listener.go:169 +0x158
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener.(*listener).WrapExpiration
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener/listener.go:155 +0x7c
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 228 [select, 902 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/google.golang.org/grpc.(*ccBalancerWrapper).watcher(0x400154ad00)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/google.golang.org/grpc/balancer_conn_wrappers.go:69 +0x90
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/google.golang.org/grpc.newCCBalancerWrapper
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/google.golang.org/grpc/balancer_conn_wrappers.go:60 +0x128
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 229 [chan receive, 902 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/google.golang.org/grpc.(*addrConn).resetTransport(0x4000936840)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/google.golang.org/grpc/clientconn.go:1179 +0x604
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/google.golang.org/grpc.(*addrConn).connect
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/google.golang.org/grpc/clientconn.go:815 +0x1a8
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 499 [chan receive, 902 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/google.golang.org/grpc.(*addrConn).resetTransport(0x40000f1340)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/google.golang.org/grpc/clientconn.go:1179 +0x604
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/google.golang.org/grpc.(*addrConn).connect
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/google.golang.org/grpc/clientconn.go:815 +0x1a8
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 187 [IO wait, 902 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: internal/poll.runtime_pollWait(0xffff79963848, 0x72, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/runtime/netpoll.go:222 +0x44
feb 16 12:46:21 mnode2 k3s[10737]: internal/poll.(*pollDesc).wait(0x4000d28198, 0x72, 0x0, 0x0, 0x3cb1062)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x38
feb 16 12:46:21 mnode2 k3s[10737]: internal/poll.(*pollDesc).waitRead(...)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
feb 16 12:46:21 mnode2 k3s[10737]: internal/poll.(*FD).Accept(0x4000d28180, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/internal/poll/fd_unix.go:394 +0x1a0
feb 16 12:46:21 mnode2 k3s[10737]: net.(*netFD).accept(0x4000d28180, 0x37bcd80, 0x1, 0x3afd880)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/net/fd_unix.go:172 +0x2c
feb 16 12:46:21 mnode2 k3s[10737]: net.(*TCPListener).accept(0x400157a300, 0x38a3580, 0xffffa0857e98, 0x40004cc000)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/net/tcpsock_posix.go:139 +0x2c
feb 16 12:46:21 mnode2 k3s[10737]: net.(*TCPListener).Accept(0x400157a300, 0x10, 0xffffa0857e98, 0x40004cc010, 0x4000506eb8)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/net/tcpsock.go:261 +0x5c
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/transport.(*rwTimeoutListener).Accept(0x400157a320, 0x15a8ddc, 0x10, 0x38a3580, 0x4000506e01)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/transport/timeout_listener.go:48 +0x34
feb 16 12:46:21 mnode2 k3s[10737]: crypto/tls.(*listener).Accept(0x4000b72b60, 0x40004cc010, 0x444d740, 0x4000f66280, 0x40004cc000)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/crypto/tls/tls.go:67 +0x34
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/transport.(*tlsListener).acceptLoop(0x400074c040)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/transport/listener_tls.go:126 +0x180
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/transport.newTLSListener
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/transport/listener_tls.go:84 +0x1d4
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 231 [select, 902 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: io.(*pipe).Read(0x4001570a20, 0x4000f7c0f6, 0xf0a, 0xf0a, 0x0, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/io/pipe.go:57 +0xa0
feb 16 12:46:21 mnode2 k3s[10737]: io.(*PipeReader).Read(0x40015920a8, 0x4000f7c0f6, 0xf0a, 0xf0a, 0x0, 0x0, 0x4)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/io/pipe.go:134 +0x44
feb 16 12:46:21 mnode2 k3s[10737]: bufio.(*Scanner).Scan(0x4009885f38, 0x1)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/bufio/scan.go:214 +0x94
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/sirupsen/logrus.(*Entry).writerScanner(0x400152f180, 0x40015920a8, 0x4000e828b0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/sirupsen/logrus/writer.go:59 +0x88
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/github.com/sirupsen/logrus.(*Entry).WriterLevel
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/sirupsen/logrus/writer.go:51 +0x188
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 232 [IO wait]:
feb 16 12:46:21 mnode2 k3s[10737]: internal/poll.runtime_pollWait(0xffff79963930, 0x72, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/runtime/netpoll.go:222 +0x44
feb 16 12:46:21 mnode2 k3s[10737]: internal/poll.(*pollDesc).wait(0x4000d29598, 0x72, 0x0, 0x0, 0x3cb1062)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x38
feb 16 12:46:21 mnode2 k3s[10737]: internal/poll.(*pollDesc).waitRead(...)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
feb 16 12:46:21 mnode2 k3s[10737]: internal/poll.(*FD).Accept(0x4000d29580, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/internal/poll/fd_unix.go:394 +0x1a0
feb 16 12:46:21 mnode2 k3s[10737]: net.(*netFD).accept(0x4000d29580, 0x40c9d0, 0xfffcf8ca1688, 0x5)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/net/fd_unix.go:172 +0x2c
feb 16 12:46:21 mnode2 k3s[10737]: net.(*TCPListener).accept(0x400156ebe0, 0x40c39c, 0x676a318, 0x9)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/net/tcpsock_posix.go:139 +0x2c
feb 16 12:46:21 mnode2 k3s[10737]: net.(*TCPListener).AcceptTCP(0x400156ebe0, 0x3, 0x4001562420, 0x40003a5e00)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/net/tcpsock.go:248 +0x5c
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener.tcpKeepAliveListener.Accept(0x400156ebe0, 0x40cff8, 0x400c56f9a0, 0x10, 0x10)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener/tcp.go:31 +0x28
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener.(*listener).Accept(0x4001562420, 0x0, 0x4000f6fdc8, 0x81701c, 0x4000f6fde8)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener/listener.go:232 +0x58
feb 16 12:46:21 mnode2 k3s[10737]: crypto/tls.(*listener).Accept(0x400156f420, 0x4000f6fe60, 0x4000f6fe68, 0x18, 0x400159e000)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/crypto/tls/tls.go:67 +0x34
feb 16 12:46:21 mnode2 k3s[10737]: net/http.(*Server).Serve(0x4001558e00, 0x440b340, 0x400156f420, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/net/http/server.go:2937 +0x218
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/pkg/cluster.(*Cluster).initClusterAndHTTPS.func1(0x4001558e00, 0x440b340, 0x400156f420)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/cluster/https.go:80 +0x38
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/pkg/cluster.(*Cluster).initClusterAndHTTPS
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/cluster/https.go:79 +0x20c
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 233 [chan receive, 902 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/pkg/cluster.(*Cluster).initClusterAndHTTPS.func2(0x444d740, 0x40014d7500, 0x4001558e00)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/cluster/https.go:86 +0x40
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/pkg/cluster.(*Cluster).initClusterAndHTTPS
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/cluster/https.go:85 +0x23c
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 234 [chan receive]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/pkg/etcd.(*ETCD).manageLearners(0x400082e6c0, 0x444d740, 0x40014d7500, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/etcd/etcd.go:557 +0x9c
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/pkg/etcd.(*ETCD).Start
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/pkg/etcd/etcd.go:219 +0xec
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 191 [select, 902 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/wal.(*filePipeline).run(0x400074c840)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/wal/file_pipeline.go:98 +0xec
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/wal.newFilePipeline
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/wal/file_pipeline.go:52 +0x110
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 254 [select]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/fileutil.purgeFile.func1(0x4000519680, 0x4000cb5f50, 0x2f, 0x40014ced20, 0x3cb2378, 0x7, 0x5, 0x40015700c0, 0x0, 0x6fc23ac00, ...)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/fileutil/purge.go:90 +0x8a8
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/fileutil.purgeFile
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/fileutil/purge.go:41 +0xa8
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 190 [syscall]:
feb 16 12:46:21 mnode2 k3s[10737]: syscall.Syscall(0x53, 0xb, 0x0, 0x0, 0x400b4cfaa8, 0x141123c, 0x4001670080)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/syscall/asm_linux_arm64.s:9 +0x10
feb 16 12:46:21 mnode2 k3s[10737]: syscall.Fdatasync(0xb, 0x1000, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /usr/local/go/src/syscall/zsyscall_linux_arm64.go:393 +0x34
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/bbolt.fdatasync(0x400149c000, 0x1000, 0x1000)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/bbolt/bolt_linux.go:9 +0x44
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/bbolt.(*Tx).writeMeta(0x40139be380, 0x0, 0x0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/bbolt/tx.go:596 +0xec
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/bbolt.(*Tx).Commit(0x40139be380, 0x31400e54929c, 0x67376c0)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/bbolt/tx.go:208 +0x2bc
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend.(*batchTx).commit(0x4000f13110, 0x4004cad100)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend/batch_tx.go:236 +0x6c
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend.(*batchTxBuffered).unsafeCommit(0x4000f13110, 0x2997000)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend/batch_tx.go:324 +0x40
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend.(*batchTxBuffered).commit(0x4000f13110, 0x3ec4b00)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend/batch_tx.go:303 +0x48
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend.(*batchTxBuffered).Commit(0x4000f13110)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend/batch_tx.go:290 +0x50
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend.(*backend).run(0x40008e8300)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend/backend.go:334 +0x134
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend.newBackend
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/mvcc/backend/backend.go:189 +0x3bc
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 192 [select]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/raft.(*node).run(0x400076c480)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/raft/node.go:337 +0x310
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/raft.RestartNode
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/raft/node.go:240 +0x278
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 211 [select, 1 minutes]:
feb 16 12:46:21 mnode2 k3s[10737]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/schedule.(*fifo).run(0x4000f62b40)
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/schedule/schedule.go:143 +0x20c
feb 16 12:46:21 mnode2 k3s[10737]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/schedule.NewFIFOScheduler
feb 16 12:46:21 mnode2 k3s[10737]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/schedule/schedule.go:70 +0x138
feb 16 12:46:21 mnode2 k3s[10737]: goroutine 621 [sync.Cond.Wait, 902 minutes]:
@luckyluc74
Copy link
Author

luckyluc74 commented Feb 16, 2021

extra crash log of mnode1

I have 3 raspberry pi running all single master nodes running same setup and not connected to each other.
3rd node, mnode3 is still running

mnode1

vcgencmd measure_temp
temp=34.5'C
vcgencmd get_throttled
throttled=0x0

mnode1
feb 16 15:58:02 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T15:58:02.662+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"151.108578ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:475"}
feb 16 15:58:02 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T15:58:02.662+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"438.911012ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-controller-manager\" ","response":"range_response_count:1 size:492"}
feb 16 15:58:02 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T15:58:02.663+0100","caller":"traceutil/trace.go:145","msg":"trace[1588630390] range","detail":"{range_begin:/registry/leases/kube-system/kube-controller-manager; range_end:; response_count:1; response_revision:107712; }","duration":"439.304264ms","start":"2021-02-16T15:58:02.224+0100","end":"2021-02-16T15:58:02.663+0100","steps":["trace[1588630390] 'agreement among raft nodes before linearized reading'  (duration: 144.918467ms)","trace[1588630390] 'range keys from in-memory index tree'  (duration: 293.922657ms)"]}
feb 16 15:58:02 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T15:58:02.663+0100","caller":"traceutil/trace.go:145","msg":"trace[1509745875] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:107712; }","duration":"151.359185ms","start":"2021-02-16T15:58:02.511+0100","end":"2021-02-16T15:58:02.663+0100","steps":["trace[1509745875] 'range keys from in-memory index tree'  (duration: 150.667939ms)"]}
feb 16 15:58:06 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T15:58:06.386+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"170.168942ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/ingress/\" range_end:\"/registry/ingress0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 15:58:06 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T15:58:06.387+0100","caller":"traceutil/trace.go:145","msg":"trace[1357271808] range","detail":"{range_begin:/registry/ingress/; range_end:/registry/ingress0; response_count:0; response_revision:107719; }","duration":"170.361698ms","start":"2021-02-16T15:58:06.216+0100","end":"2021-02-16T15:58:06.386+0100","steps":["trace[1357271808] 'agreement among raft nodes before linearized reading'  (duration: 157.605907ms)"]}
feb 16 15:58:13 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T15:58:13.270+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"229.264647ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/csinodes/\" range_end:\"/registry/csinodes0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 15:58:13 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T15:58:13.270+0100","caller":"traceutil/trace.go:145","msg":"trace[771728951] range","detail":"{range_begin:/registry/csinodes/; range_end:/registry/csinodes0; response_count:0; response_revision:107731; }","duration":"229.527068ms","start":"2021-02-16T15:58:13.040+0100","end":"2021-02-16T15:58:13.270+0100","steps":["trace[771728951] 'agreement among raft nodes before linearized reading'  (duration: 229.114557ms)"]}
feb 16 15:58:18 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T15:58:18.575+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"446.799448ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/crd.projectcalico.org/clusterinformations/default\" ","response":"range_response_count:1 size:913"}
feb 16 15:58:18 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T15:58:18.575+0100","caller":"traceutil/trace.go:145","msg":"trace[330277760] range","detail":"{range_begin:/registry/crd.projectcalico.org/clusterinformations/default; range_end:; response_count:1; response_revision:107739; }","duration":"447.095591ms","start":"2021-02-16T15:58:18.128+0100","end":"2021-02-16T15:58:18.575+0100","steps":["trace[330277760] 'agreement among raft nodes before linearized reading'  (duration: 123.077784ms)","trace[330277760] 'range keys from in-memory index tree'  (duration: 323.65835ms)"]}
feb 16 15:58:18 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T15:58:18.575+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"238.471779ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/configmaps/kube-system/k3s\" ","response":"range_response_count:1 size:499"}
feb 16 15:58:18 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T15:58:18.575+0100","caller":"traceutil/trace.go:145","msg":"trace[49556546] range","detail":"{range_begin:/registry/configmaps/kube-system/k3s; range_end:; response_count:1; response_revision:107739; }","duration":"239.035676ms","start":"2021-02-16T15:58:18.336+0100","end":"2021-02-16T15:58:18.575+0100","steps":["trace[49556546] 'range keys from in-memory index tree'  (duration: 238.066434ms)"]}
feb 16 15:58:18 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T15:58:18.577+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"449.561603ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/jobs/\" range_end:\"/registry/jobs0\" limit:500 ","response":"range_response_count:0 size:6"}
feb 16 15:58:18 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T15:58:18.578+0100","caller":"traceutil/trace.go:145","msg":"trace[613142195] range","detail":"{range_begin:/registry/jobs/; range_end:/registry/jobs0; response_count:0; response_revision:107739; }","duration":"449.796098ms","start":"2021-02-16T15:58:18.128+0100","end":"2021-02-16T15:58:18.577+0100","steps":["trace[613142195] 'agreement among raft nodes before linearized reading'  (duration: 123.01834ms)","trace[613142195] 'range keys from in-memory index tree'  (duration: 326.475301ms)"]}
feb 16 15:58:18 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T15:58:18.742+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"150.745271ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/cronjobs/\" range_end:\"/registry/cronjobs0\" limit:500 ","response":"range_response_count:0 size:6"}
feb 16 15:58:18 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T15:58:18.743+0100","caller":"traceutil/trace.go:145","msg":"trace[1585636481] range","detail":"{range_begin:/registry/cronjobs/; range_end:/registry/cronjobs0; response_count:0; response_revision:107740; }","duration":"150.993897ms","start":"2021-02-16T15:58:18.592+0100","end":"2021-02-16T15:58:18.743+0100","steps":["trace[1585636481] 'agreement among raft nodes before linearized reading'  (duration: 134.321639ms)"]}
feb 16 15:58:27 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T15:58:27.959+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"408.05829ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:475"}
feb 16 15:58:27 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T15:58:27.959+0100","caller":"traceutil/trace.go:145","msg":"trace[477151954] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:107754; }","duration":"408.381858ms","start":"2021-02-16T15:58:27.551+0100","end":"2021-02-16T15:58:27.959+0100","steps":["trace[477151954] 'range keys from in-memory index tree'  (duration: 407.802017ms)"]}
feb 16 15:58:28 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T15:58:28.480+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"414.247346ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/controllers/\" range_end:\"/registry/controllers0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 15:58:28 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T15:58:28.481+0100","caller":"traceutil/trace.go:145","msg":"trace[1817909778] range","detail":"{range_begin:/registry/controllers/; range_end:/registry/controllers0; response_count:0; response_revision:107755; }","duration":"414.847465ms","start":"2021-02-16T15:58:28.066+0100","end":"2021-02-16T15:58:28.481+0100","steps":["trace[1817909778] 'range keys from in-memory index tree'  (duration: 402.21606ms)"]}
feb 16 15:58:28 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T15:58:28.481+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"135.606598ms","expected-duration":"100ms","prefix":"","request":"header:<ID:10685484627153395432 username:\"etcd-client\" auth_revision:1 > txn:<compare:<target:MOD key:\"/registry/leases/kube-node-lease/mnode1\" mod_revision:107739 > success:<request_put:<key:\"/registry/leases/kube-node-lease/mnode1\" value_size:525 >> failure:<request_range:<key:\"/registry/leases/kube-node-lease/mnode1\" > >>","response":"size:18"}
feb 16 16:01:05 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:05.663+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"132.406478ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/crd.projectcalico.org/globalnetworkpolicies/\" range_end:\"/registry/crd.projectcalico.org/globalnetworkpolicies0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 16:01:05 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:05.664+0100","caller":"traceutil/trace.go:145","msg":"trace[1055183143] range","detail":"{range_begin:/registry/crd.projectcalico.org/globalnetworkpolicies/; range_end:/registry/crd.projectcalico.org/globalnetworkpolicies0; response_count:0; response_revision:108017; }","duration":"132.631362ms","start":"2021-02-16T16:01:05.531+0100","end":"2021-02-16T16:01:05.664+0100","steps":["trace[1055183143] 'agreement among raft nodes before linearized reading'  (duration: 132.275721ms)"]}
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.816721   21139 sysinfo.go:203] Nodes topology is not available, providing CPU topology
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.817534   21139 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu0/online: open /sys/devices/system/cpu/cpu0/online: no such file or directory
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.817624   21139 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu1/online: open /sys/devices/system/cpu/cpu1/online: no such file or directory
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.817696   21139 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu2/online: open /sys/devices/system/cpu/cpu2/online: no such file or directory
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.817764   21139 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu3/online: open /sys/devices/system/cpu/cpu3/online: no such file or directory
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.818378   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu0 online state, skipping
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.818444   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu1 online state, skipping
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.818496   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu2 online state, skipping
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.818545   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu3 online state, skipping
feb 16 16:01:11 mnode1 k3s[21139]: E0216 16:01:11.818565   21139 machine.go:72] Cannot read number of physical cores correctly, number of cores set to 0
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.818825   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu0 online state, skipping
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.818878   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu1 online state, skipping
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.818926   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu2 online state, skipping
feb 16 16:01:11 mnode1 k3s[21139]: W0216 16:01:11.818973   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu3 online state, skipping
feb 16 16:01:11 mnode1 k3s[21139]: E0216 16:01:11.818991   21139 machine.go:86] Cannot read number of sockets correctly, number of sockets set to 0
feb 16 16:01:12 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:12.252+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"525.226917ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:475"}
feb 16 16:01:12 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:12.252+0100","caller":"traceutil/trace.go:145","msg":"trace[1467648293] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:108026; }","duration":"525.559615ms","start":"2021-02-16T16:01:11.726+0100","end":"2021-02-16T16:01:12.252+0100","steps":["trace[1467648293] 'agreement among raft nodes before linearized reading'  (duration: 189.368132ms)","trace[1467648293] 'range keys from in-memory index tree'  (duration: 335.740361ms)"]}
feb 16 16:01:12 mnode1 k3s[21139]: I0216 16:01:12.255305   21139 trace.go:205] Trace[646078721]: "Get" url:/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-scheduler,user-agent:k3s/v1.20.2+k3s1 (linux/arm64) kubernetes/1d4adb0/leader-election,client:127.0.0.1 (16-Feb-2021 16:01:11.725) (total time: 529ms):
feb 16 16:01:12 mnode1 k3s[21139]: Trace[646078721]: ---"About to write a response" 529ms (16:01:00.254)
feb 16 16:01:12 mnode1 k3s[21139]: Trace[646078721]: [529.579117ms] [529.579117ms] END
feb 16 16:01:16 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:16.809+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"374.192178ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/flowschemas/exempt\" ","response":"range_response_count:1 size:880"}
feb 16 16:01:16 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:16.810+0100","caller":"traceutil/trace.go:145","msg":"trace[1538439819] range","detail":"{range_begin:/registry/flowschemas/exempt; range_end:; response_count:1; response_revision:108035; }","duration":"374.465562ms","start":"2021-02-16T16:01:16.435+0100","end":"2021-02-16T16:01:16.809+0100","steps":["trace[1538439819] 'range keys from in-memory index tree'  (duration: 367.682423ms)"]}
feb 16 16:01:17 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:17.884+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"108.644364ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/statefulsets/\" range_end:\"/registry/statefulsets0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 16:01:17 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:17.885+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"129.25346ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-controller-manager\" ","response":"range_response_count:1 size:493"}
feb 16 16:01:17 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:17.885+0100","caller":"traceutil/trace.go:145","msg":"trace[2068106763] range","detail":"{range_begin:/registry/statefulsets/; range_end:/registry/statefulsets0; response_count:0; response_revision:108036; }","duration":"109.002877ms","start":"2021-02-16T16:01:17.776+0100","end":"2021-02-16T16:01:17.885+0100","steps":["trace[2068106763] 'range keys from in-memory index tree'  (duration: 108.327018ms)"]}
feb 16 16:01:17 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:17.885+0100","caller":"traceutil/trace.go:145","msg":"trace[645829471] range","detail":"{range_begin:/registry/leases/kube-system/kube-controller-manager; range_end:; response_count:1; response_revision:108036; }","duration":"129.558992ms","start":"2021-02-16T16:01:17.755+0100","end":"2021-02-16T16:01:17.885+0100","steps":["trace[645829471] 'range keys from in-memory index tree'  (duration: 129.058779ms)"]}
feb 16 16:01:25 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:25.083+0100","caller":"mvcc/index.go:189","msg":"compact tree index","revision":107553}
feb 16 16:01:25 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:25.083+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"272.114013ms","expected-duration":"100ms","prefix":"","request":"header:<ID:10685484627153396412 username:\"etcd-client\" auth_revision:1 > compaction:<revision:107553 > ","response":"size:6"}
feb 16 16:01:25 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:25.083+0100","caller":"traceutil/trace.go:145","msg":"trace[1117879620] compact","detail":"{revision:107553; response_revision:108049; }","duration":"278.672507ms","start":"2021-02-16T16:01:24.805+0100","end":"2021-02-16T16:01:25.083+0100","steps":["trace[1117879620] 'check and update compact revision'  (duration: 271.970422ms)"]}
feb 16 16:01:25 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:25.086+0100","caller":"mvcc/kvstore_compaction.go:56","msg":"finished scheduled compaction","compact-revision":107553,"took":"2.006761ms"}
feb 16 16:01:27 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:27.325+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"131.976672ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/cronjobs/\" range_end:\"/registry/cronjobs0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 16:01:27 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:27.325+0100","caller":"traceutil/trace.go:145","msg":"trace[803039959] range","detail":"{range_begin:/registry/cronjobs/; range_end:/registry/cronjobs0; response_count:0; response_revision:108053; }","duration":"132.349239ms","start":"2021-02-16T16:01:27.193+0100","end":"2021-02-16T16:01:27.325+0100","steps":["trace[803039959] 'range keys from in-memory index tree'  (duration: 131.712918ms)"]}
feb 16 16:01:28 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:28.289+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"203.391124ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-controller-manager\" ","response":"range_response_count:1 size:492"}
feb 16 16:01:28 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:28.290+0100","caller":"traceutil/trace.go:145","msg":"trace[785805461] range","detail":"{range_begin:/registry/leases/kube-system/kube-controller-manager; range_end:; response_count:1; response_revision:108054; }","duration":"203.684712ms","start":"2021-02-16T16:01:28.086+0100","end":"2021-02-16T16:01:28.289+0100","steps":["trace[785805461] 'range keys from in-memory index tree'  (duration: 195.906961ms)"]}
feb 16 16:01:29 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:29.272+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"690.553851ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:475"}
feb 16 16:01:29 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:29.272+0100","caller":"traceutil/trace.go:145","msg":"trace[1155370573] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:108055; }","duration":"690.87166ms","start":"2021-02-16T16:01:28.581+0100","end":"2021-02-16T16:01:29.272+0100","steps":["trace[1155370573] 'agreement among raft nodes before linearized reading'  (duration: 320.087975ms)","trace[1155370573] 'range keys from in-memory index tree'  (duration: 370.349045ms)"]}
feb 16 16:01:29 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:29.272+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"224.624173ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/clusterroles/\" range_end:\"/registry/clusterroles0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 16:01:29 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:29.272+0100","caller":"traceutil/trace.go:145","msg":"trace[1573293747] range","detail":"{range_begin:/registry/clusterroles/; range_end:/registry/clusterroles0; response_count:0; response_revision:108055; }","duration":"225.156441ms","start":"2021-02-16T16:01:29.047+0100","end":"2021-02-16T16:01:29.272+0100","steps":["trace[1573293747] 'range keys from in-memory index tree'  (duration: 224.459416ms)"]}
feb 16 16:01:29 mnode1 k3s[21139]: I0216 16:01:29.274676   21139 trace.go:205] Trace[1389936483]: "Get" url:/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-scheduler,user-agent:k3s/v1.20.2+k3s1 (linux/arm64) kubernetes/1d4adb0/leader-election,client:127.0.0.1 (16-Feb-2021 16:01:28.580) (total time: 693ms):
feb 16 16:01:29 mnode1 k3s[21139]: Trace[1389936483]: ---"About to write a response" 693ms (16:01:00.274)
feb 16 16:01:29 mnode1 k3s[21139]: Trace[1389936483]: [693.83246ms] [693.83246ms] END
feb 16 16:01:32 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:32.479+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"110.103783ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-controller-manager\" ","response":"range_response_count:1 size:493"}
feb 16 16:01:32 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:32.480+0100","caller":"traceutil/trace.go:145","msg":"trace[904558844] range","detail":"{range_begin:/registry/leases/kube-system/kube-controller-manager; range_end:; response_count:1; response_revision:108060; }","duration":"110.311446ms","start":"2021-02-16T16:01:32.369+0100","end":"2021-02-16T16:01:32.480+0100","steps":["trace[904558844] 'range keys from in-memory index tree'  (duration: 109.457147ms)"]}
feb 16 16:01:48 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:48.863+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"161.302577ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/crd.projectcalico.org/blockaffinities/\" range_end:\"/registry/crd.projectcalico.org/blockaffinities0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 16:01:48 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:48.863+0100","caller":"traceutil/trace.go:145","msg":"trace[1829220651] range","detail":"{range_begin:/registry/crd.projectcalico.org/blockaffinities/; range_end:/registry/crd.projectcalico.org/blockaffinities0; response_count:0; response_revision:108088; }","duration":"161.650664ms","start":"2021-02-16T16:01:48.701+0100","end":"2021-02-16T16:01:48.863+0100","steps":["trace[1829220651] 'range keys from in-memory index tree'  (duration: 161.05886ms)"]}
feb 16 16:01:49 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:49.261+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"164.598871ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/secrets/\" range_end:\"/registry/secrets0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 16:01:49 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:49.261+0100","caller":"traceutil/trace.go:145","msg":"trace[1219745685] range","detail":"{range_begin:/registry/secrets/; range_end:/registry/secrets0; response_count:0; response_revision:108089; }","duration":"164.872569ms","start":"2021-02-16T16:01:49.096+0100","end":"2021-02-16T16:01:49.261+0100","steps":["trace[1219745685] 'agreement among raft nodes before linearized reading'  (duration: 136.769087ms)","trace[1219745685] 'range keys from in-memory index tree'  (duration: 27.781747ms)"]}
feb 16 16:01:49 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:49.261+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"238.96453ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/crd.projectcalico.org/ipamhandles/\" range_end:\"/registry/crd.projectcalico.org/ipamhandles0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 16:01:49 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:49.261+0100","caller":"traceutil/trace.go:145","msg":"trace[217085985] range","detail":"{range_begin:/registry/crd.projectcalico.org/ipamhandles/; range_end:/registry/crd.projectcalico.org/ipamhandles0; response_count:0; response_revision:108089; }","duration":"239.609259ms","start":"2021-02-16T16:01:49.022+0100","end":"2021-02-16T16:01:49.261+0100","steps":["trace[217085985] 'agreement among raft nodes before linearized reading'  (duration: 211.191357ms)","trace[217085985] 'range keys from in-memory index tree'  (duration: 27.714026ms)"]}
feb 16 16:01:53 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:53.473+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"382.742049ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/events/\" range_end:\"/registry/events0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 16:01:53 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:53.473+0100","caller":"traceutil/trace.go:145","msg":"trace[1179781776] range","detail":"{range_begin:/registry/events/; range_end:/registry/events0; response_count:0; response_revision:108095; }","duration":"383.043581ms","start":"2021-02-16T16:01:53.090+0100","end":"2021-02-16T16:01:53.473+0100","steps":["trace[1179781776] 'range keys from in-memory index tree'  (duration: 382.5907ms)"]}
feb 16 16:01:55 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:01:55.958+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"113.084564ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/masterleases/\" range_end:\"/registry/masterleases0\" ","response":"range_response_count:1 size:142"}
feb 16 16:01:55 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:01:55.958+0100","caller":"traceutil/trace.go:145","msg":"trace[152482745] range","detail":"{range_begin:/registry/masterleases/; range_end:/registry/masterleases0; response_count:1; response_revision:108102; }","duration":"113.359133ms","start":"2021-02-16T16:01:55.845+0100","end":"2021-02-16T16:01:55.958+0100","steps":["trace[152482745] 'range keys from in-memory index tree'  (duration: 112.863253ms)"]}
feb 16 16:02:03 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:02:03.410+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"261.116026ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-controller-manager\" ","response":"range_response_count:1 size:492"}
feb 16 16:02:03 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:02:03.411+0100","caller":"traceutil/trace.go:145","msg":"trace[1620390811] range","detail":"{range_begin:/registry/leases/kube-system/kube-controller-manager; range_end:; response_count:1; response_revision:108112; }","duration":"261.436039ms","start":"2021-02-16T16:02:03.149+0100","end":"2021-02-16T16:02:03.411+0100","steps":["trace[1620390811] 'range keys from in-memory index tree'  (duration: 260.857809ms)"]}
feb 16 16:02:03 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:02:03.410+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"386.274784ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/crd.projectcalico.org/bgppeers/\" range_end:\"/registry/crd.projectcalico.org/bgppeers0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 16:02:03 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:02:03.412+0100","caller":"traceutil/trace.go:145","msg":"trace[1530487145] range","detail":"{range_begin:/registry/crd.projectcalico.org/bgppeers/; range_end:/registry/crd.projectcalico.org/bgppeers0; response_count:0; response_revision:108112; }","duration":"388.007624ms","start":"2021-02-16T16:02:03.024+0100","end":"2021-02-16T16:02:03.412+0100","steps":["trace[1530487145] 'range keys from in-memory index tree'  (duration: 386.056343ms)"]}
feb 16 16:02:05 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:02:05.094+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"195.063367ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/cronjobs/\" range_end:\"/registry/cronjobs0\" limit:500 ","response":"range_response_count:0 size:6"}
feb 16 16:02:05 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:02:05.094+0100","caller":"traceutil/trace.go:145","msg":"trace[758211405] range","detail":"{range_begin:/registry/cronjobs/; range_end:/registry/cronjobs0; response_count:0; response_revision:108115; }","duration":"195.277752ms","start":"2021-02-16T16:02:04.899+0100","end":"2021-02-16T16:02:05.094+0100","steps":["trace[758211405] 'agreement among raft nodes before linearized reading'  (duration: 181.170262ms)"]}
feb 16 16:02:05 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:02:05.094+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"192.883331ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/health\" ","response":"range_response_count:0 size:6"}
feb 16 16:02:05 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:02:05.095+0100","caller":"traceutil/trace.go:145","msg":"trace[366072607] range","detail":"{range_begin:/registry/health; range_end:; response_count:0; response_revision:108116; }","duration":"192.979552ms","start":"2021-02-16T16:02:04.902+0100","end":"2021-02-16T16:02:05.095+0100","steps":["trace[366072607] 'agreement among raft nodes before linearized reading'  (duration: 192.7675ms)"]}
feb 16 16:02:08 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:02:08.439+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"138.090916ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/ingress/\" range_end:\"/registry/ingress0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 16:02:08 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:02:08.439+0100","caller":"traceutil/trace.go:145","msg":"trace[2084570304] range","detail":"{range_begin:/registry/ingress/; range_end:/registry/ingress0; response_count:0; response_revision:108122; }","duration":"138.387671ms","start":"2021-02-16T16:02:08.301+0100","end":"2021-02-16T16:02:08.439+0100","steps":["trace[2084570304] 'range keys from in-memory index tree'  (duration: 137.561722ms)"]}
feb 16 16:02:18 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:02:18.322+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"209.247338ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:474"}
feb 16 16:02:18 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:02:18.322+0100","caller":"traceutil/trace.go:145","msg":"trace[1713125482] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:108138; }","duration":"209.497537ms","start":"2021-02-16T16:02:18.112+0100","end":"2021-02-16T16:02:18.322+0100","steps":["trace[1713125482] 'range keys from in-memory index tree'  (duration: 209.051582ms)"]}
feb 16 16:05:26 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:05:26.283+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"124.052413ms","expected-duration":"100ms","prefix":"","request":"header:<ID:10685484627153397736 username:\"etcd-client\" auth_revision:1 > txn:<compare:<target:MOD key:\"/registry/masterleases/192.168.111.33\" mod_revision:108432 > success:<request_put:<key:\"/registry/masterleases/192.168.111.33\" value_size:70 lease:1462112590298621926 >> failure:<request_range:<key:\"/registry/masterleases/192.168.111.33\" > >>","response":"size:18"}
feb 16 16:05:37 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:05:37.746+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"181.203475ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:475"}
feb 16 16:05:37 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:05:37.746+0100","caller":"traceutil/trace.go:145","msg":"trace[1406579825] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:108468; }","duration":"181.485636ms","start":"2021-02-16T16:05:37.565+0100","end":"2021-02-16T16:05:37.746+0100","steps":["trace[1406579825] 'agreement among raft nodes before linearized reading'  (duration: 56.052118ms)","trace[1406579825] 'range keys from in-memory index tree'  (duration: 125.036803ms)"]}
feb 16 16:05:46 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:05:46.159+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"214.251228ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:475"}
feb 16 16:05:46 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:05:46.159+0100","caller":"traceutil/trace.go:145","msg":"trace[952148684] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:108482; }","duration":"214.519188ms","start":"2021-02-16T16:05:45.944+0100","end":"2021-02-16T16:05:46.159+0100","steps":["trace[952148684] 'range keys from in-memory index tree'  (duration: 213.971196ms)"]}
feb 16 16:05:46 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:05:46.159+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"225.694903ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/apiextensions.k8s.io/customresourcedefinitions/\" range_end:\"/registry/apiextensions.k8s.io/customresourcedefinitions0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 16:05:46 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:05:46.159+0100","caller":"traceutil/trace.go:145","msg":"trace[115718342] range","detail":"{range_begin:/registry/apiextensions.k8s.io/customresourcedefinitions/; range_end:/registry/apiextensions.k8s.io/customresourcedefinitions0; response_count:0; response_revision:108482; }","duration":"226.266377ms","start":"2021-02-16T16:05:45.933+0100","end":"2021-02-16T16:05:46.159+0100","steps":["trace[115718342] 'range keys from in-memory index tree'  (duration: 225.449314ms)"]}
feb 16 16:05:48 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:05:48.161+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"456.921799ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/configmaps/kube-system/k3s\" ","response":"range_response_count:1 size:499"}
feb 16 16:05:48 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:05:48.161+0100","caller":"traceutil/trace.go:145","msg":"trace[1804497456] range","detail":"{range_begin:/registry/configmaps/kube-system/k3s; range_end:; response_count:1; response_revision:108484; }","duration":"457.185721ms","start":"2021-02-16T16:05:47.704+0100","end":"2021-02-16T16:05:48.161+0100","steps":["trace[1804497456] 'range keys from in-memory index tree'  (duration: 456.577618ms)"]}
feb 16 16:05:48 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:05:48.489+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"298.94803ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:475"}
feb 16 16:05:48 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:05:48.489+0100","caller":"traceutil/trace.go:145","msg":"trace[2062781352] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:108485; }","duration":"299.198193ms","start":"2021-02-16T16:05:48.190+0100","end":"2021-02-16T16:05:48.489+0100","steps":["trace[2062781352] 'agreement among raft nodes before linearized reading'  (duration: 114.559148ms)","trace[2062781352] 'range keys from in-memory index tree'  (duration: 184.269402ms)"]}
feb 16 16:05:48 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:05:48.777+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"183.379377ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/ingress/\" range_end:\"/registry/ingress0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 16:05:48 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:05:48.777+0100","caller":"traceutil/trace.go:145","msg":"trace[604998816] range","detail":"{range_begin:/registry/ingress/; range_end:/registry/ingress0; response_count:0; response_revision:108486; }","duration":"183.604281ms","start":"2021-02-16T16:05:48.593+0100","end":"2021-02-16T16:05:48.777+0100","steps":["trace[604998816] 'range keys from in-memory index tree'  (duration: 182.703701ms)"]}
feb 16 16:05:55 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:05:55.967+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"124.511153ms","expected-duration":"100ms","prefix":"","request":"header:<ID:10685484627153397903 username:\"etcd-client\" auth_revision:1 > txn:<compare:<target:MOD key:\"/registry/masterleases/192.168.111.33\" mod_revision:108482 > success:<request_put:<key:\"/registry/masterleases/192.168.111.33\" value_size:70 lease:1462112590298622093 >> failure:<request_range:<key:\"/registry/masterleases/192.168.111.33\" > >>","response":"size:18"}
feb 16 16:05:58 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:05:58.884+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"210.946907ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:475"}
feb 16 16:05:58 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:05:58.884+0100","caller":"traceutil/trace.go:145","msg":"trace[1644163955] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:108502; }","duration":"211.156997ms","start":"2021-02-16T16:05:58.673+0100","end":"2021-02-16T16:05:58.884+0100","steps":["trace[1644163955] 'range keys from in-memory index tree'  (duration: 210.768947ms)"]}
feb 16 16:05:58 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:05:58.884+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"111.991214ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/\" range_end:\"/registry/leases0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 16:05:58 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:05:58.886+0100","caller":"traceutil/trace.go:145","msg":"trace[22626504] range","detail":"{range_begin:/registry/leases/; range_end:/registry/leases0; response_count:0; response_revision:108502; }","duration":"113.599155ms","start":"2021-02-16T16:05:58.772+0100","end":"2021-02-16T16:05:58.886+0100","steps":["trace[22626504] 'range keys from in-memory index tree'  (duration: 111.741829ms)"]}
feb 16 16:05:58 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:05:58.884+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"577.949728ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/roles/\" range_end:\"/registry/roles0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 16:05:58 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:05:58.887+0100","caller":"traceutil/trace.go:145","msg":"trace[1885737635] range","detail":"{range_begin:/registry/roles/; range_end:/registry/roles0; response_count:0; response_revision:108502; }","duration":"581.216479ms","start":"2021-02-16T16:05:58.306+0100","end":"2021-02-16T16:05:58.887+0100","steps":["trace[1885737635] 'agreement among raft nodes before linearized reading'  (duration: 107.154671ms)","trace[1885737635] 'range keys from in-memory index tree'  (duration: 470.738669ms)"]}
feb 16 16:06:04 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:06:04.523+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"169.799179ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/configmaps/kube-system/k3s\" ","response":"range_response_count:1 size:499"}
feb 16 16:06:04 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:04.523+0100","caller":"traceutil/trace.go:145","msg":"trace[139197091] range","detail":"{range_begin:/registry/configmaps/kube-system/k3s; range_end:; response_count:1; response_revision:108511; }","duration":"170.087545ms","start":"2021-02-16T16:06:04.353+0100","end":"2021-02-16T16:06:04.523+0100","steps":["trace[139197091] 'range keys from in-memory index tree'  (duration: 169.483146ms)"]}
feb 16 16:06:06 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:06:06.017+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"159.298566ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/masterleases/\" range_end:\"/registry/masterleases0\" ","response":"range_response_count:1 size:142"}
feb 16 16:06:06 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:06.017+0100","caller":"traceutil/trace.go:145","msg":"trace[733595962] range","detail":"{range_begin:/registry/masterleases/; range_end:/registry/masterleases0; response_count:1; response_revision:108514; }","duration":"159.542673ms","start":"2021-02-16T16:06:05.858+0100","end":"2021-02-16T16:06:06.017+0100","steps":["trace[733595962] 'range keys from in-memory index tree'  (duration: 158.818091ms)"]}
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.816866   21139 sysinfo.go:203] Nodes topology is not available, providing CPU topology
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.817706   21139 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu0/online: open /sys/devices/system/cpu/cpu0/online: no such file or directory
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.817798   21139 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu1/online: open /sys/devices/system/cpu/cpu1/online: no such file or directory
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.817874   21139 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu2/online: open /sys/devices/system/cpu/cpu2/online: no such file or directory
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.817941   21139 sysfs.go:348] unable to read /sys/devices/system/cpu/cpu3/online: open /sys/devices/system/cpu/cpu3/online: no such file or directory
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.818514   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu0 online state, skipping
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.818579   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu1 online state, skipping
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.818630   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu2 online state, skipping
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.818680   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu3 online state, skipping
feb 16 16:06:11 mnode1 k3s[21139]: E0216 16:06:11.818699   21139 machine.go:72] Cannot read number of physical cores correctly, number of cores set to 0
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.818961   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu0 online state, skipping
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.819015   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu1 online state, skipping
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.819063   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu2 online state, skipping
feb 16 16:06:11 mnode1 k3s[21139]: W0216 16:06:11.819110   21139 machine.go:253] Cannot determine CPU /sys/bus/cpu/devices/cpu3 online state, skipping
feb 16 16:06:11 mnode1 k3s[21139]: E0216 16:06:11.819127   21139 machine.go:86] Cannot read number of sockets correctly, number of sockets set to 0
feb 16 16:06:15 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:06:15.135+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"743.629973ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/events/\" range_end:\"/registry/events0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 16:06:15 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:06:15.135+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"498.923728ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/configmaps/kube-system/k3s\" ","response":"range_response_count:1 size:499"}
feb 16 16:06:15 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:15.135+0100","caller":"traceutil/trace.go:145","msg":"trace[1142705321] range","detail":"{range_begin:/registry/configmaps/kube-system/k3s; range_end:; response_count:1; response_revision:108528; }","duration":"499.486553ms","start":"2021-02-16T16:06:14.636+0100","end":"2021-02-16T16:06:15.135+0100","steps":["trace[1142705321] 'agreement among raft nodes before linearized reading'  (duration: 140.911945ms)","trace[1142705321] 'range keys from in-memory index tree'  (duration: 357.921283ms)"]}
feb 16 16:06:15 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:15.135+0100","caller":"traceutil/trace.go:145","msg":"trace[62413282] range","detail":"{range_begin:/registry/events/; range_end:/registry/events0; response_count:0; response_revision:108528; }","duration":"744.055912ms","start":"2021-02-16T16:06:14.391+0100","end":"2021-02-16T16:06:15.135+0100","steps":["trace[62413282] 'agreement among raft nodes before linearized reading'  (duration: 385.60584ms)","trace[62413282] 'range keys from in-memory index tree'  (duration: 357.949339ms)"]}
feb 16 16:06:15 mnode1 k3s[21139]: I0216 16:06:15.137851   21139 trace.go:205] Trace[1057638231]: "Get" url:/api/v1/namespaces/kube-system/configmaps/k3s,user-agent:k3s/v1.20.2+k3s1 (linux/arm64) kubernetes/1d4adb0,client:127.0.0.1 (16-Feb-2021 16:06:14.634) (total time: 503ms):
feb 16 16:06:15 mnode1 k3s[21139]: Trace[1057638231]: ---"About to write a response" 502ms (16:06:00.137)
feb 16 16:06:15 mnode1 k3s[21139]: Trace[1057638231]: [503.075614ms] [503.075614ms] END
feb 16 16:06:15 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:06:15.273+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"107.954871ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:474"}
feb 16 16:06:15 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:15.273+0100","caller":"traceutil/trace.go:145","msg":"trace[1031367683] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:108529; }","duration":"108.131536ms","start":"2021-02-16T16:06:15.165+0100","end":"2021-02-16T16:06:15.273+0100","steps":["trace[1031367683] 'agreement among raft nodes before linearized reading'  (duration: 102.637428ms)"]}
feb 16 16:06:19 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:06:19.454+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"104.220273ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:475"}
feb 16 16:06:19 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:19.454+0100","caller":"traceutil/trace.go:145","msg":"trace[1519280899] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:108536; }","duration":"104.699674ms","start":"2021-02-16T16:06:19.350+0100","end":"2021-02-16T16:06:19.454+0100","steps":["trace[1519280899] 'range keys from in-memory index tree'  (duration: 104.011406ms)"]}
feb 16 16:06:25 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:25.102+0100","caller":"mvcc/index.go:189","msg":"compact tree index","revision":108049}
feb 16 16:06:25 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:25.106+0100","caller":"mvcc/kvstore_compaction.go:56","msg":"finished scheduled compaction","compact-revision":108049,"took":"3.178789ms"}
feb 16 16:06:29 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:06:29.275+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"433.513797ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/mutatingwebhookconfigurations/\" range_end:\"/registry/mutatingwebhookconfigurations0\" count_only:true ","response":"range_response_count:0 size:6"}
feb 16 16:06:29 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:29.275+0100","caller":"traceutil/trace.go:145","msg":"trace[1110394581] range","detail":"{range_begin:/registry/mutatingwebhookconfigurations/; range_end:/registry/mutatingwebhookconfigurations0; response_count:0; response_revision:108553; }","duration":"433.806144ms","start":"2021-02-16T16:06:28.841+0100","end":"2021-02-16T16:06:29.275+0100","steps":["trace[1110394581] 'agreement among raft nodes before linearized reading'  (duration: 228.889542ms)","trace[1110394581] 'range keys from in-memory index tree'  (duration: 204.563015ms)"]}
feb 16 16:06:29 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:06:29.946+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"312.702782ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"range_response_count:1 size:475"}
feb 16 16:06:29 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:29.946+0100","caller":"traceutil/trace.go:145","msg":"trace[159338868] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; response_count:1; response_revision:108554; }","duration":"313.045036ms","start":"2021-02-16T16:06:29.633+0100","end":"2021-02-16T16:06:29.946+0100","steps":["trace[159338868] 'range keys from in-memory index tree'  (duration: 312.463378ms)"]}
feb 16 16:06:30 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:06:30.671+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"539.917084ms","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/prioritylevelconfigurations/\" range_end:\"/registry/prioritylevelconfigurations0\" count_only:true ","response":"range_response_count:0 size:8"}
feb 16 16:06:30 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:30.671+0100","caller":"traceutil/trace.go:145","msg":"trace[2021636467] range","detail":"{range_begin:/registry/prioritylevelconfigurations/; range_end:/registry/prioritylevelconfigurations0; response_count:0; response_revision:108555; }","duration":"540.217284ms","start":"2021-02-16T16:06:30.131+0100","end":"2021-02-16T16:06:30.671+0100","steps":["trace[2021636467] 'range keys from in-memory index tree'  (duration: 539.660662ms)"]}
feb 16 16:06:46 mnode1 k3s[21139]: E0216 16:06:46.051125   21139 leaderelection.go:325] error retrieving resource lock kube-system/kube-scheduler: Get "https://127.0.0.1:6444/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-scheduler?timeout=10s": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
feb 16 16:06:46 mnode1 k3s[21139]: I0216 16:06:46.051358   21139 leaderelection.go:278] failed to renew lease kube-system/kube-scheduler: timed out waiting for the condition
feb 16 16:06:46 mnode1 k3s[21139]: F0216 16:06:46.051459   21139 server.go:205] leaderelection lost
feb 16 16:06:46 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:06:46.233+0100","caller":"etcdserver/util.go:163","msg":"apply request took too long","took":"10.167657803s","expected-duration":"100ms","prefix":"read-only range ","request":"key:\"/registry/leases/kube-system/kube-scheduler\" ","response":"","error":"context canceled"}
feb 16 16:06:46 mnode1 k3s[21139]: {"level":"info","ts":"2021-02-16T16:06:46.233+0100","caller":"traceutil/trace.go:145","msg":"trace[1485506545] range","detail":"{range_begin:/registry/leases/kube-system/kube-scheduler; range_end:; }","duration":"10.167827412s","start":"2021-02-16T16:06:36.065+0100","end":"2021-02-16T16:06:46.233+0100","steps":["trace[1485506545] 'agreement among raft nodes before linearized reading'  (duration: 10.167653766s)"]}
feb 16 16:06:46 mnode1 k3s[21139]: {"level":"warn","ts":"2021-02-16T16:06:46.233+0100","caller":"grpclog/grpclog.go:60","msg":"grpc: Server.processUnaryRPC failed to write status: connection error: desc = \"transport is closing\""}
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 5772 [running]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/klog/v2.stacks(0x4000010001, 0x4005617420, 0x41, 0xd5)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:1026 +0xac
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/klog/v2.(*loggingT).output(0x6739880, 0x4000000003, 0x0, 0x0, 0x40086ba230, 0x63b9faf, 0x9, 0xcd, 0x0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:975 +0x168
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/klog/v2.(*loggingT).printf(0x6739880, 0x3, 0x0, 0x0, 0x0, 0x0, 0x3cdc8d5, 0x13, 0x0, 0x0, ...)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:750 +0x12c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/klog/v2.Fatalf(...)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:1502
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app.Run.func3()
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:205 +0x90
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/client-go/tools/leaderelection.(*LeaderElector).Run.func1(0x400c6fe5a0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/client-go/tools/leaderelection/leaderelection.go:199 +0x2c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/client-go/tools/leaderelection.(*LeaderElector).Run(0x400c6fe5a0, 0x444d740, 0x400e95be40)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/client-go/tools/leaderelection/leaderelection.go:209 +0x130
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app.Run(0x444d740, 0x4012eaa700, 0x40130a4d18, 0x40137f0a80, 0x0, 0x0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:213 +0x470
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app.runCommand(0x40079cc580, 0x400753cd00, 0x0, 0x0, 0x0, 0x0, 0x0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:132 +0x104
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app.NewSchedulerCommand.func1(0x40079cc580, 0x4012eba120, 0x0, 0x6)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:81 +0x48
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/spf13/cobra.(*Command).execute(0x40079cc580, 0x400799aa00, 0x6, 0x8, 0x40079cc580, 0x400799aa00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/spf13/cobra/command.go:854 +0x1c4
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0x40079cc580, 0x0, 0x0, 0x1)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/spf13/cobra/command.go:958 +0x268
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/spf13/cobra.(*Command).Execute(...)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/spf13/cobra/command.go:895
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/pkg/daemons/executor.Embedded.Scheduler.func1(0x40026f84e0, 0x40079cc580)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/daemons/executor/embed.go:67 +0x38
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/pkg/daemons/executor.Embedded.Scheduler
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/daemons/executor/embed.go:65 +0x7c
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 1 [chan receive, 1085 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/pkg/agent.run(0x444d740, 0x4001547900, 0x40013b6a10, 0x6a, 0x0, 0x0, 0x0, 0x0, 0x4003b25a20, 0x16, ...)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/agent/run.go:121 +0x1c4
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/pkg/agent.Run(0x444d740, 0x4001547900, 0x40013b6a10, 0x6a, 0x0, 0x0, 0x0, 0x0, 0x4003b25a20, 0x16, ...)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/agent/run.go:172 +0x2fc
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/pkg/cli/server.run(0x40015362c0, 0x673a740, 0x40014cae78, 0x48)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/cli/server/server.go:283 +0x123c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/pkg/cli/server.Run(0x40015362c0, 0x0, 0x0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/cli/server/server.go:38 +0x58
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/urfave/cli.HandleAction(0x35694c0, 0x3eb7160, 0x40015362c0, 0x40015362c0, 0x0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/urfave/cli/app.go:523 +0x118
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/urfave/cli.Command.Run(0x3caf617, 0x6, 0x0, 0x0, 0x0, 0x0, 0x0, 0x3ce3b73, 0x15, 0x4001538d00, ...)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/urfave/cli/command.go:174 +0x41c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/urfave/cli.(*App).Run(0x4001222a80, 0x4000070900, 0x10, 0x10, 0x0, 0x0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/urfave/cli/app.go:276 +0x584
feb 16 16:06:46 mnode1 k3s[21139]: main.main()
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/cmd/server/main.go:47 +0x4d8
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 4 [chan receive, 1 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/klog/v2.(*loggingT).flushDaemon(0x6739880)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:1169 +0x70
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/k8s.io/klog/v2.init.0
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/v2/klog.go:417 +0x124
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 6 [chan receive, 1 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/klog.(*loggingT).flushDaemon(0x67395c0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/klog.go:1010 +0x70
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/k8s.io/klog.init.0
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/klog/klog.go:411 +0x118
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 17610 [chan receive, 1085 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/client-go/tools/record.(*eventBroadcasterImpl).StartEventWatcher.func1(0x43f6dc0, 0x40150f5710, 0x4008dddb90)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/client-go/tools/record/event.go:301 +0x98
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/k8s.io/client-go/tools/record.(*eventBroadcasterImpl).StartEventWatcher
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/client-go/tools/record/event.go:299 +0x64
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 77 [sleep, 1 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: time.Sleep(0x3b9aca00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/runtime/time.go:188 +0xc0
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/kubernetes/pkg/scheduler/framework/runtime.(*metricsRecorder).run(0x4000e546f0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/pkg/scheduler/framework/runtime/metrics_recorder.go:88 +0x3c
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/k8s.io/kubernetes/pkg/scheduler/framework/runtime.newMetricsRecorder
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kubernetes/pkg/scheduler/framework/runtime/metrics_recorder.go:60 +0xf0
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 196 [chan receive]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop(0x4000fa11e0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:173 +0x2d0
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.NewMergeLogger
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:91 +0x7c
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 149 [chan receive]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop(0x4000fa0cc0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:173 +0x2d0
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.NewMergeLogger
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:91 +0x7c
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 199 [chan receive]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop(0x4000fa13e0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:173 +0x2d0
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil.NewMergeLogger
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/go.etcd.io/etcd/pkg/logutil/merge_logger.go:91 +0x7c
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 185 [syscall, 1086 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: os/signal.signal_recv(0x40009f2300)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/runtime/sigqueue.go:147 +0xc4
feb 16 16:06:46 mnode1 k3s[21139]: os/signal.loop()
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/os/signal/signal_unix.go:23 +0x20
feb 16 16:06:46 mnode1 k3s[21139]: created by os/signal.Notify.func1.1
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/os/signal/signal.go:150 +0x44
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 174 [chan receive, 1086 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/signals.SetupSignalHandler.func1(0x400153f020, 0x4001049a60)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/signals/signal.go:37 +0x2c
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/signals.SetupSignalHandler
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/wrangler/pkg/signals/signal.go:36 +0xdc
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 187 [select, 6 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener.(*listener).WrapExpiration.func1(0x4000963ce0, 0x5a, 0x444d740, 0x4000ffb780)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener/listener.go:169 +0x158
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener.(*listener).WrapExpiration
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener/listener.go:155 +0x7c
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 188 [select, 1085 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/google.golang.org/grpc.(*ccBalancerWrapper).watcher(0x4000ffbb00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/google.golang.org/grpc/balancer_conn_wrappers.go:69 +0x90
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/google.golang.org/grpc.newCCBalancerWrapper
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/google.golang.org/grpc/balancer_conn_wrappers.go:60 +0x128
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 189 [chan receive, 1085 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/google.golang.org/grpc.(*addrConn).resetTransport(0x40001fcdc0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/google.golang.org/grpc/clientconn.go:1179 +0x604
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/google.golang.org/grpc.(*addrConn).connect
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/google.golang.org/grpc/clientconn.go:815 +0x1a8
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 8495376 [select, 5 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/storage/cacher.(*cacheWatcher).process(0x40085cf650, 0x444d7c0, 0x40207acba0, 0x6770838, 0x0, 0x0, 0x19a44)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/storage/cacher/cacher.go:1395 +0x1d8
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/storage/cacher.(*Cacher).Watch
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/storage/cacher/cacher.go:519 +0x42c
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 208 [select, 51 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/handlers.(*WatchServer).ServeHTTP(0x401b8fed00, 0x4427780, 0x400c00cb90, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/handlers/watch.go:213 +0x980
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/handlers.serveWatch(0x43f7e00, 0x400b043340, 0x401258a340, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/handlers/watch.go:138 +0x6e4
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/handlers.ListResource.func1.2()
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/handlers/get.go:269 +0x98
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/metrics.RecordLongRunning(0x4019047a00, 0x40164a48f0, 0x3cb6bdd, 0x9, 0x4009a3c420)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go:392 +0x248
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/handlers.ListResource.func1(0x4427780, 0x400c00cb90, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/handlers/get.go:268 +0x8ac
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/metrics.InstrumentHandlerFunc.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go:474 +0x1f8
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x401671e780, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters.WithWaitGroup.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters/waitgroup.go:59 +0xf8
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x401942e7b0, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiextensions-apiserver/pkg/apiserver.(*crdHandler).ServeHTTP(0x4001a85440, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiextensions-apiserver/pkg/apiserver/customresource_handler.go:380 +0x6bc
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux.(*pathHandler).ServeHTTP(0x4008dd15c0, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:248 +0x39c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).ServeHTTP(0x40001b5b90, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:234 +0x7c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server.director.ServeHTTP(0x3ced5aa, 0x17, 0x4001c193b0, 0x40001b5b90, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/handler.go:154 +0x6dc
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux.(*pathHandler).ServeHTTP(0x400c34fa80, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:254 +0x1dc
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).ServeHTTP(0x400047aa80, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:234 +0x7c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server.director.ServeHTTP(0x3cc7ab0, 0xe, 0x4001136000, 0x400047aa80, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/handler.go:154 +0x6dc
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/kube-aggregator/pkg/apiserver.(*proxyHandler).ServeHTTP(0x40027245f0, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy.go:121 +0x10c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux.(*pathHandler).ServeHTTP(0x4007778640, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:248 +0x39c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).ServeHTTP(0x40074f9b90, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:234 +0x7c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server.director.ServeHTTP(0x3ccb928, 0xf, 0x40058293b0, 0x40074f9b90, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/handler.go:154 +0x6dc
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:95 +0x138
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007527c20, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithAuthorization.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters/authorization.go:64 +0x450
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007513140, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:71 +0x134
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007513180, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:95 +0x138
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007527c50, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters.WithPriorityAndFairness.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters/priority-and-fairness.go:90 +0x1ec
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007527c80, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:71 +0x134
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x40075131c0, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:95 +0x138
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007527cb0, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithImpersonation.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters/impersonation.go:50 +0x1cec
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007513200, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:71 +0x134
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007513240, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:95 +0x138
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007527ce0, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:71 +0x134
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007513280, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1(0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:95 +0x138
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007527d40, 0x4427980, 0x400b0432d0, 0x4019047a00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithAuthentication.func1(0x4427980, 0x400b0432d0, 0x4019047800)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters/authentication.go:70 +0x53c
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x40074af090, 0x4427980, 0x400b0432d0, 0x4019047800)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1(0x4427980, 0x400b0432d0, 0x4019047700)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:80 +0x2f8
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x40075132c0, 0x4427980, 0x400b0432d0, 0x4019047700)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP(0x4007523260, 0x4427980, 0x400b0432d0, 0x4019047700)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:90 +0x36c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters.WithWaitGroup.func1(0x4427980, 0x400b0432d0, 0x4019047700)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters/waitgroup.go:59 +0xf8
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007527d70, 0x4427980, 0x400b0432d0, 0x4019047700)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithRequestInfo.func1(0x4427980, 0x400b0432d0, 0x4019047600)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters/requestinfo.go:39 +0x200
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007527da0, 0x4427980, 0x400b0432d0, 0x4019047600)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithWarningRecorder.func1(0x4427980, 0x400b0432d0, 0x4019047500)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters/warning.go:35 +0x174
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007523280, 0x4427980, 0x400b0432d0, 0x4019047500)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithCacheControl.func1(0x4427980, 0x400b0432d0, 0x4019047500)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters/cachecontrol.go:31 +0x98
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x40075232a0, 0x4427980, 0x400b0432d0, 0x4019047500)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters.withRequestReceivedTimestampWithClock.func1(0x4427980, 0x400b0432d0, 0x4019047400)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters/request_received_time.go:38 +0x150
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007527dd0, 0x4427980, 0x400b0432d0, 0x4019047400)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/httplog.WithLogging.func1(0x442e580, 0x4007d2cee0, 0x4019047300)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:91 +0x288
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x40075232e0, 0x442e580, 0x4007d2cee0, 0x4019047300)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters.withPanicRecovery.func1(0x442e580, 0x4007d2cee0, 0x4019047300)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters/wrap.go:70 +0xc8
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4007523300, 0x442e580, 0x4007d2cee0, 0x4019047300)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server.(*APIServerHandler).ServeHTTP(0x4007527e00, 0x442e580, 0x4007d2cee0, 0x4019047300)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/handler.go:189 +0x4c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/gorilla/mux.(*Router).ServeHTTP(0x400247cb40, 0x442e580, 0x4007d2cee0, 0x4019047100)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/gorilla/mux/mux.go:210 +0x9c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/gorilla/mux.(*Router).ServeHTTP(0x400247cc00, 0x442e580, 0x4007d2cee0, 0x4019046f00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/gorilla/mux/mux.go:210 +0x9c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/gorilla/mux.(*Router).ServeHTTP(0x400247d5c0, 0x442e580, 0x4007d2cee0, 0x4019046b00)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/gorilla/mux/mux.go:210 +0x9c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/gorilla/mux.(*Router).ServeHTTP(0x400247d800, 0x442e580, 0x4007d2cee0, 0x4019046900)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/gorilla/mux/mux.go:210 +0x9c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/pkg/cluster.(*Cluster).router.func1(0x442e580, 0x4007d2cee0, 0x4019046900)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/cluster/router.go:27 +0x54
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x4001124dd0, 0x442e580, 0x4007d2cee0, 0x4019046900)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/pkg/cluster.(*Cluster).getHandler.func1(0x442e580, 0x4007d2cee0, 0x4019046900)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/cluster/router.go:14 +0x84
feb 16 16:06:46 mnode1 k3s[21139]: net/http.HandlerFunc.ServeHTTP(0x40012cbfb0, 0x442e580, 0x4007d2cee0, 0x4019046900)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2042 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/gorilla/mux.(*Router).ServeHTTP(0x400137a0c0, 0x442e580, 0x4007d2cee0, 0x4019046700)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/gorilla/mux/mux.go:210 +0x9c
feb 16 16:06:46 mnode1 k3s[21139]: net/http.serverHandler.ServeHTTP(0x400024d0a0, 0x442e580, 0x4007d2cee0, 0x4019046700)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2843 +0xbc
feb 16 16:06:46 mnode1 k3s[21139]: net/http.(*conn).serve(0x4000709180, 0x444d740, 0x4001336b00)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:1925 +0x6f4
feb 16 16:06:46 mnode1 k3s[21139]: created by net/http.(*Server).Serve
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2969 +0x2e8
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 191 [select, 1085 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: io.(*pipe).Read(0x4000d6f8c0, 0x40010fa0f6, 0xf0a, 0xf0a, 0x0, 0x0, 0x0)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/io/pipe.go:57 +0xa0
feb 16 16:06:46 mnode1 k3s[21139]: io.(*PipeReader).Read(0x40001e4430, 0x40010fa0f6, 0xf0a, 0xf0a, 0x0, 0x0, 0x4)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/io/pipe.go:134 +0x44
feb 16 16:06:46 mnode1 k3s[21139]: bufio.(*Scanner).Scan(0x4007796f38, 0x1)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/bufio/scan.go:214 +0x94
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/sirupsen/logrus.(*Entry).writerScanner(0x40010b3880, 0x40001e4430, 0x4001125990)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/sirupsen/logrus/writer.go:59 +0x88
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/vendor/github.com/sirupsen/logrus.(*Entry).WriterLevel
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/sirupsen/logrus/writer.go:51 +0x188
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 192 [IO wait, 2 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: internal/poll.runtime_pollWait(0xffff63c7b730, 0x72, 0x0)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/runtime/netpoll.go:222 +0x44
feb 16 16:06:46 mnode1 k3s[21139]: internal/poll.(*pollDesc).wait(0x4000d02098, 0x72, 0x0, 0x0, 0x3cb1062)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x38
feb 16 16:06:46 mnode1 k3s[21139]: internal/poll.(*pollDesc).waitRead(...)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
feb 16 16:06:46 mnode1 k3s[21139]: internal/poll.(*FD).Accept(0x4000d02080, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/internal/poll/fd_unix.go:394 +0x1a0
feb 16 16:06:46 mnode1 k3s[21139]: net.(*netFD).accept(0x4000d02080, 0x40c9d0, 0x40001f5c00, 0xffff638e0628)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/fd_unix.go:172 +0x2c
feb 16 16:06:46 mnode1 k3s[21139]: net.(*TCPListener).accept(0x4000702ea0, 0x8, 0x40001f5b10, 0x2b6f140)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/tcpsock_posix.go:139 +0x2c
feb 16 16:06:46 mnode1 k3s[21139]: net.(*TCPListener).AcceptTCP(0x4000702ea0, 0x0, 0x4000963ce0, 0x4000438140)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/tcpsock.go:248 +0x5c
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener.tcpKeepAliveListener.Accept(0x4000702ea0, 0x40cff8, 0x400ba912c0, 0x10, 0x10)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener/tcp.go:31 +0x28
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener.(*listener).Accept(0x4000963ce0, 0x0, 0x40001f5dc8, 0x81701c, 0x40001f5de8)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/vendor/github.com/rancher/dynamiclistener/listener.go:232 +0x58
feb 16 16:06:46 mnode1 k3s[21139]: crypto/tls.(*listener).Accept(0x4000703f20, 0x40001f5e60, 0x40001f5e68, 0x18, 0x4000c5b080)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/crypto/tls/tls.go:67 +0x34
feb 16 16:06:46 mnode1 k3s[21139]: net/http.(*Server).Serve(0x400024d0a0, 0x440b340, 0x4000703f20, 0x0, 0x0)
feb 16 16:06:46 mnode1 k3s[21139]:         /usr/local/go/src/net/http/server.go:2937 +0x218
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/pkg/cluster.(*Cluster).initClusterAndHTTPS.func1(0x400024d0a0, 0x440b340, 0x4000703f20)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/cluster/https.go:80 +0x38
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/pkg/cluster.(*Cluster).initClusterAndHTTPS
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/cluster/https.go:79 +0x20c
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 193 [chan receive, 1086 minutes]:
feb 16 16:06:46 mnode1 k3s[21139]: github.com/rancher/k3s/pkg/cluster.(*Cluster).initClusterAndHTTPS.func2(0x444d740, 0x4001547900, 0x400024d0a0)
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/cluster/https.go:86 +0x40
feb 16 16:06:46 mnode1 k3s[21139]: created by github.com/rancher/k3s/pkg/cluster.(*Cluster).initClusterAndHTTPS
feb 16 16:06:46 mnode1 k3s[21139]:         /go/src/github.com/rancher/k3s/pkg/cluster/https.go:85 +0x23c
feb 16 16:06:46 mnode1 k3s[21139]: goroutine 210 [select, 1 minutes]:

@luckyluc74
Copy link
Author

luckyluc74 commented Feb 16, 2021

extra info this is mnode 3 with exact same hard en software setup but still running
To give an idea of ''load' mnode1 and mnode2 were running

mnode3

root@mnode3:~# kubectl get all -A
NAMESPACE       NAME                                                     READY   STATUS    RESTARTS   AGE
k8s-dashboard   pod/k8sdashboard-kubernetes-dashboard-789bf4885c-pfvph   1/1     Running   0          45h
k8s-dashboard   pod/svclb-k8sdashboard-kubernetes-dashboard-mdn47        1/1     Running   0          45h
kube-system     pod/calico-kube-controllers-86bddfcff-rkfjw              1/1     Running   0          45h
kube-system     pod/calico-node-xhj6f                                    1/1     Running   0          45h
kube-system     pod/coredns-854c77959c-tfjcg                             1/1     Running   0          45h

NAMESPACE       NAME                                        TYPE           CLUSTER-IP    EXTERNAL-IP      PORT(S)                  AGE
default         service/kubernetes                          ClusterIP      10.43.0.1     <none>           443/TCP                  45h
k8s-dashboard   service/k8sdashboard-kubernetes-dashboard   LoadBalancer   10.43.13.33   192.168.111.35   8432:32545/TCP           45h
kube-system     service/kube-dns                            ClusterIP      10.43.0.10    <none>           53/UDP,53/TCP,9153/TCP   45h

NAMESPACE       NAME                                                     DESIRED   CURRENT   READY   UP-TO-DATE   AVAILABLE   NODE SELECTOR            AGE
k8s-dashboard   daemonset.apps/svclb-k8sdashboard-kubernetes-dashboard   1         1         1       1            1           <none>                   45h
kube-system     daemonset.apps/calico-node                               1         1         1       1            1           kubernetes.io/os=linux   45h

NAMESPACE       NAME                                                READY   UP-TO-DATE   AVAILABLE   AGE
k8s-dashboard   deployment.apps/k8sdashboard-kubernetes-dashboard   1/1     1            1           45h
kube-system     deployment.apps/calico-kube-controllers             1/1     1            1           45h
kube-system     deployment.apps/coredns                             1/1     1            1           45h

NAMESPACE       NAME                                                           DESIRED   CURRENT   READY   AGE
k8s-dashboard   replicaset.apps/k8sdashboard-kubernetes-dashboard-789bf4885c   1         1         1       45h
kube-system     replicaset.apps/calico-kube-controllers-86bddfcff              1         1         1       45h
kube-system     replicaset.apps/coredns-854c77959c                             1         1         1       45h

top

top - 20:23:43 up 2 days, 18 min,  2 users,  load average: 1.10, 1.68, 1.91
Tasks: 227 total,   1 running, 226 sleeping,   0 stopped,   0 zombie
%Cpu(s):  7.7 us,  5.6 sy,  0.0 ni, 86.3 id,  0.1 wa,  0.0 hi,  0.4 si,  0.0 st
MiB Mem :   7860.9 total,   3496.1 free,   2978.4 used,   1386.4 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.   5016.0 avail Mem

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
 268302 root      20   0   11.4g 662876  59212 S  37.3   8.2 864:05.83 k3s-server
 281125 root      20   0  755480  39484  19520 S   3.3   0.5 101:49.65 calico-node
   3519 root      20   0 1870984  72436  20352 S   1.7   0.9  60:03.55 containerd
 280935 root      20   0  111236   9500   4596 S   1.3   0.1  36:37.49 containerd-shim
 668338 root      20   0   10928   2920   2184 R   1.3   0.0   0:01.02 top
   1196 root      19  -1  320076 208696 207452 S   1.0   2.6   9:46.76 systemd-journal
 282153 root      20   0  743556  27592  14260 S   1.0   0.3  26:07.16 coredns
 292544 root      20   0   11220   2968   2188 S   0.7   0.0  26:22.72 top
      1 root      20   0  170892  10400   5452 S   0.3   0.1   6:47.28 systemd
     30 root      20   0       0      0      0 S   0.3   0.0   1:46.63 ksoftirqd/3
    450 root      20   0       0      0      0 S   0.3   0.0   9:43.68 usb-storage
   1853 root      20   0   81816   1996   1700 S   0.3   0.0   0:20.17 irqbalance
   1856 syslog    20   0  221996   4136   2360 S   0.3   0.1   4:33.69 rsyslogd
 632429 root      20   0       0      0      0 I   0.3   0.0   0:03.60 kworker/0:2-events
 638616 root      20   0       0      0      0 I   0.3   0.0   0:02.54 kworker/1:2-events
 652304 root      20   0       0      0      0 I   0.3   0.0   0:00.72 kworker/2:0-events
 664005 root      20   0       0      0      0 I   0.3   0.0   0:00.79 kworker/3:2-events
2625598 root      20   0   16252   6308   5080 S   0.3   0.1   0:00.74 sshd

@brandond
Copy link
Member

brandond commented Feb 16, 2021

Can you attach (rather than paste inline) complete logs from all three nodes? The ultimate cause of the crash is the usual - excessive etcd latency causing a failure to renew a critical controller lease:

feb 16 12:46:06 mnode2 k3s[10737]: {"level":"info","ts":"2021-02-16T12:46:06.696+0100","caller":"traceutil/trace.go:145","msg":"trace[306188567] range","detail":"{range_begin:/registry/storageclasses/; range_end:/registry/storageclasses0; response_count:0; response_revision:90422; }","duration":"133.157068ms","start":"2021-02-16T12:46:06.563+0100","end":"2021-02-16T12:46:06.696+0100","steps":["trace[306188567] 'range keys from in-memory index tree'  (duration: 130.295443ms)"]}
feb 16 12:46:20 mnode2 k3s[10737]: E0216 12:46:20.142784   10737 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
feb 16 12:46:20 mnode2 k3s[10737]: I0216 12:46:20.147102   10737 trace.go:205] Trace[873651971]: "Get" url:/apis/crd.projectcalico.org/v1/clusterinformations/default,user-agent:Go-http-client/1.1,client:172.16.102.67 (16-Feb-2021 12:46:10.149) (total time: 9997ms):
feb 16 12:46:20 mnode2 k3s[10737]: Trace[873651971]: [9.997222741s] [9.997222741s] END
feb 16 12:46:20 mnode2 k3s[10737]: E0216 12:46:20.287834   10737 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
feb 16 12:46:20 mnode2 k3s[10737]: E0216 12:46:20.287834   10737 leaderelection.go:325] error retrieving resource lock kube-system/kube-scheduler: Get "https://127.0.0.1:6444/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-scheduler?timeout=10s": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
feb 16 12:46:20 mnode2 k3s[10737]: I0216 12:46:20.288875   10737 leaderelection.go:278] failed to renew lease kube-system/kube-scheduler: timed out waiting for the condition
feb 16 12:46:20 mnode2 k3s[10737]: I0216 12:46:20.288879   10737 trace.go:205] Trace[532990064]: "Get" url:/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-scheduler,user-agent:k3s/v1.20.2+k3s1 (linux/arm64) kubernetes/1d4adb0/leader-election,client:127.0.0.1 (16-Feb-2021 12:46:10.299) (total time: 9989ms):
feb 16 12:46:20 mnode2 k3s[10737]: Trace[532990064]: [9.989502206s] [9.989502206s] END
feb 16 12:46:20 mnode2 k3s[10737]: F0216 12:46:20.289715   10737 server.go:205] leaderelection lost

You'll need to correlate other system activity to figure out why etcd wasn't responding properly. The usual cause of this is IO contention (something else doing a burst of heavy IO) on one of the etcd servers that prevents it from acknowledging writes in a timely manner. Are you using SD cards, or external USB-attached storage? Etcd pushes an EXTREMEMLY high write volume that will quickly burn out SD cards, especially smaller ones.

@luckyluc74
Copy link
Author

luckyluc74 commented Feb 16, 2021

@brandond thanks for your quick reply.

FYI I do not do anything on these pi4, besides running an idle k3s cluster.
Because I try to see if I can get these running for 2 weeks without any node crashing to see if k3s is running stable on my pi4 8gb.
No sd card is used in my pi4. I use 2x samsung fit 128GB usb3.1 usb drive on the 2 usb 3 ports of the pi.

moreinfo,
zpool status of mnode2

root@mnode2:~# zpool status
 pool: rpool
state: ONLINE
 scan: scrub repaired 0B in 0 days 00:02:10 with 0 errors on Mon Feb 15 22:05:03 2021
config:

       NAME                                                        STATE     READ WRITE CKSUM
       rpool                                                       ONLINE       0     0     0
         mirror-0                                                  ONLINE       0     0     0
           usb-Samsung_Flash_Drive_FIT_XXXXXXXXXXXXXXX-0:0-part2  ONLINE       0     0     0
           usb-Samsung_Flash_Drive_FIT_XXXXXXXXXXXXXXX-0:0-part2  ONLINE       0     0     0

errors: No known data errors

note: I have only the beginning for a couple of hours and the end for a couple of hours because of journal vacuuming settings.
But I think these log would give a good insight. Both mnode1 and mnode2 crashed.
Also these pi are not in a cluster with each other. Just running standalone.

mnode1 (crashed and zombie)
k3s-logs-20210215-2333-pi45.txt
k3s-logs-20210216-1742-pi45.txt

mnode2 (crashed and zombie)
k3s-logs-20210215-2333-pi46.txt
k3s-logs-20210216-1357-pi46.txt

mnode3 ( crashed feb 16 21:13:58 CET, but recovered )
k3s-logs-20210216-2319-pi47.txt

extra these are bonnie++ tests

mnode1

root@mnode1:~# bonnie++ -u root
Version  1.98       ------Sequential Output------ --Sequential Input- --Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Name:Size etc        /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
mnode1       15720M   29k  99 39.9m  32 32.6m  35   70k  99  328m  99  6973 1335
Latency               285ms   28031us   33486us     120ms     536us   20873us
Version  1.98       ------Sequential Create------ --------Random Create--------
mnode1              -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16 -641706944  95 +++++ +++ -641706864   4 -641706824  38 +++++ +++ -641706744   3
Latency             10045us   31286us    4815ms     228ms     334us   11551ms
1.98,1.98,mnode1,1,1613510833,15720M,,8192,5,29,99,40839,32,33393,35,70,99,335749,99,6973,1335,16,,,,,6016,95,+++++,+++,194,4,2373,38,+++++,+++,154,3,285ms,28031us,33486us,120ms,536us,20873us,10045us,31286us,4815ms,228ms,334us,11551ms

mnode2

root@mnode2:~/scripts# bonnie++ -u root
Version  1.98       ------Sequential Output------ --Sequential Input- --Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Name:Size etc        /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
mnode2       15720M   30k  97 61.4m  43 76.0m  67   76k  99  348m  99  7195 1369
Latency               282ms   36772us   25213us     122ms     492us   17940us
Version  1.98       ------Sequential Create------ --------Random Create--------
mnode2              -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16 -825176816  96 +++++ +++ -825176736   7 -825176696  95 +++++ +++ -825176616   4
Latency              9633us   30487us    3373ms    9379us     221us    5262ms
1.98,1.98,mnode2,1,1613512094,15720M,,8192,5,30,97,62869,43,77829,67,76,99,356047,99,7195,1369,16,,,,,6889,96,+++++,+++,389,7,68           15,95,+++++,+++,224,4,282ms,36772us,25213us,122ms,492us,17940us,9633us,30487us,3373ms,9379us,221us,5262ms

mnode3

root@mnode3:~/scripts# bonnie++ -u root
Version  1.98       ------Sequential Output------ --Sequential Input- --Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Name:Size etc        /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
mnode3       15720M   28k  99 84.0m  59 82.6m  78   69k  99  329m  99  6601 961
Latency               341ms   57232us   65421us     143ms    8863us   42582us
Version  1.98       ------Sequential Create------ --------Random Create--------
mnode3              -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16 -157070032  42 +++++ +++ -157069952  11 -157069912  45 +++++ +++ -157069832   7
Latency              9717us   30864us    5191ms    9552us   10607us    5702ms
1.98,1.98,mnode3,1,1613200388,15720M,,8192,5,28,99,86007,59,84606,78,69,99,336829,99,6601,961,16,,,,,2692,42,+++++,+++,528,11,2996,45,+++++,+++,327,7,341ms,57232us,65421us,143ms,8863us,42582us,9717us,30864us,5191ms,9552us,10607us,5702ms

@luckyluc74
Copy link
Author

extra

this is iostat of mnode3 which is still running. To give you an idea of disk "load"
mnode3 iostat 2021-02-16 2311 CET.txt

@brandond
Copy link
Member

brandond commented Feb 16, 2021

Can you show iostat from the period in which the nodes are crashing? These latencies are WAY higher than I would expect to see from SSDs. Have you tried this same configuration with either a single SSD in the pool, and/or a single SSD using a different filesystem (xfs/ext4)?

Also, if you are planning on running standalone nodes and don't need any HA, you might try just using the default sqlite instead of etcd, as it is MUCH less demanding in terms of IO throughput and latency.

feb 15 21:56:03 mnode1 k3s[10568]: {"level":"info","ts":"2021-02-15T21:56:03.400+0100","caller":"traceutil/trace.go:145","msg":"trace[1656112872] range","detail":"{range_begin:/registry/rolebindings/; range_end:/registry/rolebindings0; response_count:8; response_revision:696; }","duration":"22.88483547s","start":"2021-02-15T21:55:40.515+0100","end":"2021-02-15T21:56:03.400+0100","steps":["trace[1656112872] 'agreement among raft nodes before linearized reading'  (duration: 18.32118302s)","trace[1656112872] 'range keys from in-memory index tree'  (duration: 4.563533802s)"]}
feb 15 21:56:03 mnode1 k3s[10568]: {"level":"info","ts":"2021-02-15T21:56:03.401+0100","caller":"traceutil/trace.go:145","msg":"trace[1562936767] range","detail":"{range_begin:/registry/limitranges/; range_end:/registry/limitranges0; response_count:0; response_revision:696; }","duration":"23.830698521s","start":"2021-02-15T21:55:39.570+0100","end":"2021-02-15T21:56:03.400+0100","steps":["trace[1562936767] 'agreement among raft nodes before linearized reading'  (duration: 19.266859107s)","trace[1562936767] 'range keys from in-memory index tree'  (duration: 4.563767339s)"]}
feb 15 21:56:03 mnode1 k3s[10568]: {"level":"info","ts":"2021-02-15T21:56:03.401+0100","caller":"traceutil/trace.go:145","msg":"trace[1908966142] range","detail":"{range_begin:/registry/rolebindings/; range_end:/registry/rolebindings0; response_count:0; response_revision:696; }","duration":"22.885205787s","start":"2021-02-15T21:55:40.515+0100","end":"2021-02-15T21:56:03.401+0100","steps":["trace[1908966142] 'agreement among raft nodes before linearized reading'  (duration: 18.321208391s)","trace[1908966142] 'range keys from in-memory index tree'  (duration: 4.563947451s)"]}
feb 15 21:56:03 mnode1 k3s[10568]: {"level":"info","ts":"2021-02-15T21:56:03.401+0100","caller":"traceutil/trace.go:145","msg":"trace[1351211598] range","detail":"{range_begin:/registry/events/; range_end:/registry/events0; response_count:0; response_revision:696; }","duration":"23.847038942s","start":"2021-02-15T21:55:39.554+0100","end":"2021-02-15T21:56:03.401+0100","steps":["trace[1351211598] 'agreement among raft nodes before linearized reading'  (duration: 19.282860324s)","trace[1351211598] 'range keys from in-memory index tree'  (duration: 4.564132747s)"]}
feb 15 21:56:03 mnode1 k3s[10568]: {"level":"info","ts":"2021-02-15T21:56:03.401+0100","caller":"traceutil/trace.go:145","msg":"trace[730062915] range","detail":"{range_begin:/registry/roles/; range_end:/registry/roles0; response_count:8; response_revision:696; }","duration":"22.901089743s","start":"2021-02-15T21:55:40.500+0100","end":"2021-02-15T21:56:03.401+0100","steps":["trace[730062915] 'agreement among raft nodes before linearized reading'  (duration: 18.336669217s)","trace[730062915] 'range keys from in-memory index tree'  (duration: 4.564282415s)"]}

@luckyluc74
Copy link
Author

luckyluc74 commented Feb 17, 2021

@brandond

I did not run iostat while the nodes were running, but I can start new tests on all nodes and run iostat besides k3s.

Would this be a good settings for iostat? And would you like to have other statistics collected?

iostat -t -x 5 > iostat-log.txt

FYI I am using flash drive samsung fit 128GB usb3.1 usb stick , not an ssd.
Currently I am exclusively using ZFS with Root on ZFS on PI4.

I can also make other test setups besides the above nodes

  1. with real SSD ( I have 2x Samsung 860 EVO 1TB which I can use )
  2. with the Samsung fit 129GB usb stick with ext4
    to see if I can reproduce it also in these configurations.

My plan is to eventually run 4 PI4 8GB + 4xPi4 4GB nodes in cluster. But first I need to see if 1 single RPI4 8GB node with no load running on it, is stable and not crashing.

What is interesting is that mnode1 and mnode2 are crashing and k3s process remains a zombie process, while mnode3 eventually also crashed with same error(leaderelection lost) but automatically restarts k3s successfully.

To be clear all 3 PI4 nodes have exactly same hardware specs and software setup.

Hardware specs

  • raspberrry pi 4 8GB
  • 2x samsung fit 128GB usb3.1 usb stick
  • Flirc case ( has excellent cooling properties )
  • official raspberry PI4 power supply DC 5.1V 3A output

Software specs

  • ubuntu 20.10 arm64
  • v1.20.2+k3s1 (1d4adb0) go version go1.15.5

@brandond
Copy link
Member

Ah OK, so it's just a generic USB flash drive? I have a Pi4 that is booting off a 128GB NVME drive in a USB3 NVME enclosure and it works great. "Thumb drive" type devices may be a bit more limited in terms of performance.

@luckyluc74
Copy link
Author

@brandond

Small update, when I run k3s same hardware and os and same settings but use ext4 instead of zfs then it runs stable.
It now runs for more then 2 weeks on 8 pi's without any issues.

My guess is that {async} zfs icm with usb thumb drive is causing the crash on k3s with etcd.
I will close this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants