aganesh-suse
commented
10 months ago Validated on release-1.26 branch with version v1.26.10-rc2+k3s1
Environment Details
Infrastructure
- [x] Cloud
- [ ] Hosted
Node(s) CPU architecture, OS, and Version:
$ cat /etc/os-release
PRETTY_NAME="Ubuntu 22.04.2 LTS"
$ uname -m
x86_64Cluster Configuration:
HA: 3 server/ 1 agentConfig.yaml:
token: xxxx
cluster-init: true
write-kubeconfig-mode: "0644"
node-external-ip: 1.1.1.1
node-label:
- k3s-upgrade=serverTesting Steps
- Copy config.yaml
$ sudo mkdir -p /etc/rancher/k3s && sudo cp config.yaml /etc/rancher/k3s - Install k3s
curl -sfL https://get.k3s.io | sudo INSTALL_K3S_VERSION='v1.26.10-rc2+k3s1' sh -s - server - Verify Cluster Status:
kubectl get nodes -o wide kubectl get pods -A - Apply some workloads
- Save etcd snapshot:
sudo k3s etcd-snapshot save --s3 --s3-bucket=xxxx --s3-folder=xxxx --s3-region=xxxx --s3-access-key=xxxx --s3-secret-key="xxxx" - Kill servers 2 and 3:
sudo k3s-killall.sh - Stop k3s server on server1
sudo systemctl stop k3s - Run cluster reset from s3 snapshot saved:
sudo k3s server --cluster-reset --etcd-s3 --cluster-reset-restore-path=on-demand-ip-1-1-1-1-1698343463 --etcd-s3-bucket=xxxx --etcd-s3-folder=xxxx --etcd-s3-region=xxxx --etcd-s3-access-key=xxxx --etcd-s3-secret-key="xxxx" --token=xxxx - Start k3s services on servers 1, 2 and 3:
sudo systemctl start k3s - Make sure all pods/services are running as expected in the k3s cluster - including the workloads stored in the snapshot
kubectl get nodes -o wide kubectl get pods -A
Validation Results:
- k3s version used for validation:
$ k3s -v k3s version v1.26.10-rc2+k3s1 (a6687b59) go version go1.20.10
Cluster reset with s3 snapshot result:
$ sudo k3s server --cluster-reset --etcd-s3 --cluster-reset-restore-path=on-demand-ip-4-4-4-4-1698514340 --etcd-s3-bucket=xxxx --etcd-s3-folder=xxxx --etcd-s3-region=xxxx --etcd-s3-access-key=xxxx --etcd-s3-secret-key="xxxx" --token=xxxx --debug 2>&1 | tee -a /home/ubuntu/cluster_reset_output-9045
time="2023-10-28T21:48:05Z" level=warning msg="remove /var/lib/rancher/k3s/agent/etc/k3s-agent-load-balancer.json: no such file or directory"
time="2023-10-28T21:48:05Z" level=warning msg="remove /var/lib/rancher/k3s/agent/etc/k3s-api-server-agent-load-balancer.json: no such file or directory"
time="2023-10-28T21:48:05Z" level=info msg="Starting k3s v1.26.10-rc2+k3s1 (a6687b59)"
time="2023-10-28T21:48:05Z" level=info msg="Managed etcd cluster bootstrap already complete and initialized"
time="2023-10-28T21:48:05Z" level=info msg="Starting temporary etcd to reconcile with datastore"
{"level":"info","ts":"2023-10-28T21:48:05.225591Z","caller":"embed/etcd.go:127","msg":"configuring peer listeners","listen-peer-urls":["http://127.0.0.1:2400"]}
{"level":"info","ts":"2023-10-28T21:48:05.225815Z","caller":"embed/etcd.go:135","msg":"configuring client listeners","listen-client-urls":["http://127.0.0.1:2399"]}
{"level":"info","ts":"2023-10-28T21:48:05.225947Z","caller":"embed/etcd.go:309","msg":"starting an etcd server","etcd-version":"3.5.9","git-sha":"Not provided (use ./build instead of go build)","go-version":"go1.20.10","go-os":"linux","go-arch":"amd64","max-cpu-set":2,"max-cpu-available":2,"member-initialized":true,"name":"ip-4-4-4-4-1094b2cf","data-dir":"/var/lib/rancher/k3s/server/db/etcd-tmp","wal-dir":"","wal-dir-dedicated":"","member-dir":"/var/lib/rancher/k3s/server/db/etcd-tmp/member","force-new-cluster":true,"heartbeat-interval":"500ms","election-timeout":"5s","initial-election-tick-advance":true,"snapshot-count":10000,"max-wals":0,"max-snapshots":0,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["http://127.0.0.1:2400"],"listen-peer-urls":["http://127.0.0.1:2400"],"advertise-client-urls":["http://127.0.0.1:2399"],"listen-client-urls":["http://127.0.0.1:2399"],"listen-metrics-urls":[],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"","initial-cluster-state":"new","initial-cluster-token":"","quota-backend-bytes":2147483648,"max-request-bytes":1572864,"max-concurrent-streams":4294967295,"pre-vote":true,"initial-corrupt-check":true,"corrupt-check-time-interval":"0s","compact-check-time-enabled":false,"compact-check-time-interval":"1m0s","auto-compaction-mode":"","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":"","downgrade-check-interval":"5s"}
{"level":"info","ts":"2023-10-28T21:48:05.228772Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"/var/lib/rancher/k3s/server/db/etcd-tmp/member/snap/db","took":"2.535593ms"}
{"level":"info","ts":"2023-10-28T21:48:05.244769Z","caller":"etcdserver/server.go:530","msg":"No snapshot found. Recovering WAL from scratch!"}
{"level":"info","ts":"2023-10-28T21:48:05.271662Z","caller":"etcdserver/raft.go:573","msg":"discarding uncommitted WAL entries","entry-index":2800,"commit-index-from-wal":2799,"number-of-discarded-entries":5}
{"level":"info","ts":"2023-10-28T21:48:05.282944Z","caller":"etcdserver/raft.go:603","msg":"forcing restart member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","commit-index":2801}
{"level":"info","ts":"2023-10-28T21:48:05.283119Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=()"}
{"level":"info","ts":"2023-10-28T21:48:05.283169Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became follower at term 3"}
{"level":"info","ts":"2023-10-28T21:48:05.283256Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft a8142d3343e761f [peers: [], term: 3, commit: 2801, applied: 0, lastindex: 2801, lastterm: 3]"}
{"level":"warn","ts":"2023-10-28T21:48:05.314967Z","caller":"auth/store.go:1238","msg":"simple token is not cryptographically signed"}
{"level":"info","ts":"2023-10-28T21:48:05.321412Z","caller":"mvcc/kvstore.go:393","msg":"kvstore restored","current-rev":2577}
{"level":"info","ts":"2023-10-28T21:48:05.323431Z","caller":"etcdserver/quota.go:94","msg":"enabled backend quota with default value","quota-name":"v3-applier","quota-size-bytes":2147483648,"quota-size":"2.1 GB"}
{"level":"info","ts":"2023-10-28T21:48:05.325078Z","caller":"etcdserver/corrupt.go:95","msg":"starting initial corruption check","local-member-id":"a8142d3343e761f","timeout":"15s"}
{"level":"info","ts":"2023-10-28T21:48:05.326603Z","caller":"etcdserver/corrupt.go:165","msg":"initial corruption checking passed; no corruption","local-member-id":"a8142d3343e761f"}
{"level":"info","ts":"2023-10-28T21:48:05.327591Z","caller":"etcdserver/server.go:854","msg":"starting etcd server","local-member-id":"a8142d3343e761f","local-server-version":"3.5.9","cluster-version":"to_be_decided"}
{"level":"info","ts":"2023-10-28T21:48:05.33052Z","caller":"etcdserver/server.go:754","msg":"starting initial election tick advance","election-ticks":10}
{"level":"info","ts":"2023-10-28T21:48:05.33136Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359)"}
{"level":"info","ts":"2023-10-28T21:48:05.331507Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","added-peer-id":"a8142d3343e761f","added-peer-peer-urls":["https://1-1-2-2:2380"]}
{"level":"info","ts":"2023-10-28T21:48:05.331689Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","cluster-version":"3.5"}
{"level":"info","ts":"2023-10-28T21:48:05.331838Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"}
{"level":"info","ts":"2023-10-28T21:48:05.33553Z","caller":"embed/etcd.go:278","msg":"now serving peer/client/metrics","local-member-id":"a8142d3343e761f","initial-advertise-peer-urls":["http://127.0.0.1:2400"],"listen-peer-urls":["http://127.0.0.1:2400"],"advertise-client-urls":["http://127.0.0.1:2399"],"listen-client-urls":["http://127.0.0.1:2399"],"listen-metrics-urls":[]}
{"level":"info","ts":"2023-10-28T21:48:05.335873Z","caller":"embed/etcd.go:597","msg":"serving peer traffic","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T21:48:05.335898Z","caller":"embed/etcd.go:569","msg":"cmux::serve","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T21:48:05.338253Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359) learners=(5718614405625706941)"}
{"level":"info","ts":"2023-10-28T21:48:05.338317Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","added-peer-id":"4f5c9980dec079bd","added-peer-peer-urls":["https://172.31.25.138:2380"]}
{"level":"info","ts":"2023-10-28T21:48:05.338344Z","caller":"rafthttp/peer.go:133","msg":"starting remote peer","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.33839Z","caller":"rafthttp/pipeline.go:72","msg":"started HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.338658Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.338795Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.338874Z","caller":"rafthttp/peer.go:137","msg":"started remote peer","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.338906Z","caller":"rafthttp/transport.go:317","msg":"added remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"4f5c9980dec079bd","remote-peer-urls":["https://172.31.25.138:2380"]}
{"level":"info","ts":"2023-10-28T21:48:05.338893Z","caller":"rafthttp/stream.go:395","msg":"started stream reader with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"a8142d3343e761f","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.339354Z","caller":"rafthttp/stream.go:395","msg":"started stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.340737Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 5718614405625706941)"}
{"level":"info","ts":"2023-10-28T21:48:05.340789Z","caller":"membership/cluster.go:535","msg":"promote member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f"}
{"level":"info","ts":"2023-10-28T21:48:05.341998Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 5718614405625706941) learners=(4543005344029913133)"}
{"level":"info","ts":"2023-10-28T21:48:05.342116Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","added-peer-id":"3f0bff4a5f9ab02d","added-peer-peer-urls":["https://172.31.26.211:2380"]}
{"level":"info","ts":"2023-10-28T21:48:05.342146Z","caller":"rafthttp/peer.go:133","msg":"starting remote peer","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.342168Z","caller":"rafthttp/pipeline.go:72","msg":"started HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.342376Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.342841Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.343604Z","caller":"rafthttp/peer.go:137","msg":"started remote peer","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.343638Z","caller":"rafthttp/transport.go:317","msg":"added remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"3f0bff4a5f9ab02d","remote-peer-urls":["https://172.31.26.211:2380"]}
{"level":"info","ts":"2023-10-28T21:48:05.344427Z","caller":"rafthttp/stream.go:395","msg":"started stream reader with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"a8142d3343e761f","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.344653Z","caller":"rafthttp/stream.go:395","msg":"started stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.345169Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 4543005344029913133 5718614405625706941)"}
{"level":"info","ts":"2023-10-28T21:48:05.345251Z","caller":"membership/cluster.go:535","msg":"promote member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f"}
{"level":"info","ts":"2023-10-28T21:48:05.363712Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 5718614405625706941)"}
{"level":"info","ts":"2023-10-28T21:48:05.363867Z","caller":"membership/cluster.go:472","msg":"removed member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"3f0bff4a5f9ab02d","removed-remote-peer-urls":["https://172.31.26.211:2380"]}
{"level":"info","ts":"2023-10-28T21:48:05.363892Z","caller":"rafthttp/peer.go:330","msg":"stopping remote peer","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.363914Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.363945Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.363987Z","caller":"rafthttp/pipeline.go:85","msg":"stopped HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.364008Z","caller":"rafthttp/stream.go:442","msg":"stopped stream reader with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"a8142d3343e761f","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.364034Z","caller":"rafthttp/stream.go:442","msg":"stopped stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.364053Z","caller":"rafthttp/peer.go:335","msg":"stopped remote peer","remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.36407Z","caller":"rafthttp/transport.go:355","msg":"removed remote peer","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"3f0bff4a5f9ab02d"}
{"level":"info","ts":"2023-10-28T21:48:05.36416Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359)"}
{"level":"info","ts":"2023-10-28T21:48:05.364278Z","caller":"membership/cluster.go:472","msg":"removed member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"4f5c9980dec079bd","removed-remote-peer-urls":["https://172.31.25.138:2380"]}
{"level":"info","ts":"2023-10-28T21:48:05.364303Z","caller":"rafthttp/peer.go:330","msg":"stopping remote peer","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.36432Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.364349Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.364419Z","caller":"rafthttp/pipeline.go:85","msg":"stopped HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.36444Z","caller":"rafthttp/stream.go:442","msg":"stopped stream reader with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"a8142d3343e761f","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.364465Z","caller":"rafthttp/stream.go:442","msg":"stopped stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.36453Z","caller":"rafthttp/peer.go:335","msg":"stopped remote peer","remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:05.36455Z","caller":"rafthttp/transport.go:355","msg":"removed remote peer","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"4f5c9980dec079bd"}
{"level":"info","ts":"2023-10-28T21:48:12.284441Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f is starting a new election at term 3"}
{"level":"info","ts":"2023-10-28T21:48:12.284498Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became pre-candidate at term 3"}
{"level":"info","ts":"2023-10-28T21:48:12.284519Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f received MsgPreVoteResp from a8142d3343e761f at term 3"}
{"level":"info","ts":"2023-10-28T21:48:12.284534Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became candidate at term 4"}
{"level":"info","ts":"2023-10-28T21:48:12.284544Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f received MsgVoteResp from a8142d3343e761f at term 4"}
{"level":"info","ts":"2023-10-28T21:48:12.284561Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became leader at term 4"}
{"level":"info","ts":"2023-10-28T21:48:12.28457Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: a8142d3343e761f elected leader a8142d3343e761f at term 4"}
{"level":"info","ts":"2023-10-28T21:48:12.286059Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T21:48:12.286066Z","caller":"etcdserver/server.go:2064","msg":"published local member to cluster through raft","local-member-id":"a8142d3343e761f","local-member-attributes":"{Name:ip-4-4-4-4-1094b2cf ClientURLs:[http://127.0.0.1:2399]}","request-path":"/0/members/a8142d3343e761f/attributes","cluster-id":"bcbdcaabf4d4714c","publish-timeout":"15s"}
{"level":"info","ts":"2023-10-28T21:48:12.286109Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T21:48:12.286393Z","caller":"embed/serve.go:187","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"http","address":"127.0.0.1:2402"}
{"level":"info","ts":"2023-10-28T21:48:12.28877Z","caller":"embed/serve.go:187","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc","address":"127.0.0.1:2399"}
time="2023-10-28T21:48:12Z" level=info msg="Defragmenting etcd database"
{"level":"info","ts":"2023-10-28T21:48:12.295034Z","caller":"v3rpc/maintenance.go:90","msg":"starting defragment"}
{"level":"info","ts":"2023-10-28T21:48:12.302046Z","caller":"backend/backend.go:497","msg":"defragmenting","path":"/var/lib/rancher/k3s/server/db/etcd-tmp/member/snap/db","current-db-size-bytes":4792320,"current-db-size":"4.8 MB","current-db-size-in-use-bytes":4788224,"current-db-size-in-use":"4.8 MB"}
{"level":"info","ts":"2023-10-28T21:48:12.418446Z","caller":"backend/backend.go:549","msg":"finished defragmenting directory","path":"/var/lib/rancher/k3s/server/db/etcd-tmp/member/snap/db","current-db-size-bytes-diff":-253952,"current-db-size-bytes":4538368,"current-db-size":"4.5 MB","current-db-size-in-use-bytes-diff":-258048,"current-db-size-in-use-bytes":4530176,"current-db-size-in-use":"4.5 MB","took":"123.276415ms"}
{"level":"info","ts":"2023-10-28T21:48:12.418566Z","caller":"v3rpc/maintenance.go:96","msg":"finished defragment"}
time="2023-10-28T21:48:12Z" level=info msg="etcd temporary data store connection OK"
time="2023-10-28T21:48:12Z" level=info msg="Reconciling bootstrap data between datastore and disk"
time="2023-10-28T21:48:12Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T21:48:12Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling ETCDPeerCA at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.crt'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling ETCDServerCA at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.crt'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling ETCDServerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.key'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling RequestHeaderCAKey at '/var/lib/rancher/k3s/server/tls/request-header-ca.key'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling ServerCAKey at '/var/lib/rancher/k3s/server/tls/server-ca.key'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling ServiceKey at '/var/lib/rancher/k3s/server/tls/service.key'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling ClientCAKey at '/var/lib/rancher/k3s/server/tls/client-ca.key'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling ETCDPeerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.key'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling IPSECKey at '/var/lib/rancher/k3s/server/cred/ipsec.psk'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling PasswdFile at '/var/lib/rancher/k3s/server/cred/passwd'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling RequestHeaderCA at '/var/lib/rancher/k3s/server/tls/request-header-ca.crt'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling ServerCA at '/var/lib/rancher/k3s/server/tls/server-ca.crt'"
time="2023-10-28T21:48:12Z" level=debug msg="Reconciling ClientCA at '/var/lib/rancher/k3s/server/tls/client-ca.crt'"
time="2023-10-28T21:48:12Z" level=info msg="Cluster reset: backing up certificates directory to /var/lib/rancher/k3s/server/tls-1698529692"
time="2023-10-28T21:48:12Z" level=warning msg="Updating bootstrap data on disk from datastore"
time="2023-10-28T21:48:12Z" level=info msg="stopping etcd"
{"level":"info","ts":"2023-10-28T21:48:12.432452Z","caller":"embed/etcd.go:376","msg":"closing etcd server","name":"ip-4-4-4-4-1094b2cf","data-dir":"/var/lib/rancher/k3s/server/db/etcd-tmp","advertise-peer-urls":["http://127.0.0.1:2400"],"advertise-client-urls":["http://127.0.0.1:2399"]}
{"level":"info","ts":"2023-10-28T21:48:12.433213Z","caller":"etcdserver/server.go:1465","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"a8142d3343e761f","current-leader-member-id":"a8142d3343e761f"}
time="2023-10-28T21:48:12Z" level=info msg="Retrieving etcd snapshot on-demand-ip-4-4-4-4-1698529562 from S3"
time="2023-10-28T21:48:12Z" level=info msg="Checking if S3 bucket xxxx exists"
{"level":"info","ts":"2023-10-28T21:48:12.451484Z","caller":"embed/etcd.go:579","msg":"stopping serving peer traffic","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T21:48:12.45174Z","caller":"embed/etcd.go:584","msg":"stopped serving peer traffic","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T21:48:12.451764Z","caller":"embed/etcd.go:378","msg":"closed etcd server","name":"ip-4-4-4-4-1094b2cf","data-dir":"/var/lib/rancher/k3s/server/db/etcd-tmp","advertise-peer-urls":["http://127.0.0.1:2400"],"advertise-client-urls":["http://127.0.0.1:2399"]}
time="2023-10-28T21:48:12Z" level=info msg="S3 bucket xxxx exists"
time="2023-10-28T21:48:12Z" level=debug msg="Skip setting S3 snapshot cluster ID and token during cluster-reset"
time="2023-10-28T21:48:12Z" level=debug msg="Downloading snapshot from s3://xxxx/xxxx/on-demand-ip-4-4-4-4-1698529562"
time="2023-10-28T21:48:12Z" level=debug msg="Downloading snapshot metadata from s3://xxxx/xxxx/.metadata/on-demand-ip-4-4-4-4-1698529562"
time="2023-10-28T21:48:12Z" level=info msg="S3 download complete for /var/lib/rancher/k3s/server/db/snapshots/on-demand-ip-4-4-4-4-1698529562"
time="2023-10-28T21:48:12Z" level=info msg="Pre-restore etcd database moved to /var/lib/rancher/k3s/server/db/etcd-old-1698529692"
{"level":"info","ts":"2023-10-28T21:48:12.743632Z","caller":"snapshot/v3_snapshot.go:248","msg":"restoring snapshot","path":"/var/lib/rancher/k3s/server/db/snapshots/on-demand-ip-4-4-4-4-1698529562","wal-dir":"/var/lib/rancher/k3s/server/db/etcd/member/wal","data-dir":"/var/lib/rancher/k3s/server/db/etcd","snap-dir":"/var/lib/rancher/k3s/server/db/etcd/member/snap","stack":"go.etcd.io/etcd/etcdutl/v3/snapshot.(*v3Manager).Restore\n\t/go/pkg/mod/github.com/k3s-io/etcd/etcdutl/v3@v3.5.9-k3s1/snapshot/v3_snapshot.go:254\ngithub.com/k3s-io/k3s/pkg/etcd.(*ETCD).Restore\n\t/go/src/github.com/k3s-io/k3s/pkg/etcd/etcd.go:1273\ngithub.com/k3s-io/k3s/pkg/etcd.(*ETCD).Reset\n\t/go/src/github.com/k3s-io/k3s/pkg/etcd/etcd.go:374\ngithub.com/k3s-io/k3s/pkg/cluster.(*Cluster).start\n\t/go/src/github.com/k3s-io/k3s/pkg/cluster/managed.go:70\ngithub.com/k3s-io/k3s/pkg/cluster.(*Cluster).Start\n\t/go/src/github.com/k3s-io/k3s/pkg/cluster/cluster.go:75\ngithub.com/k3s-io/k3s/pkg/daemons/control.prepare\n\t/go/src/github.com/k3s-io/k3s/pkg/daemons/control/server.go:270\ngithub.com/k3s-io/k3s/pkg/daemons/control.Server\n\t/go/src/github.com/k3s-io/k3s/pkg/daemons/control/server.go:33\ngithub.com/k3s-io/k3s/pkg/server.StartServer\n\t/go/src/github.com/k3s-io/k3s/pkg/server/server.go:56\ngithub.com/k3s-io/k3s/pkg/cli/server.run\n\t/go/src/github.com/k3s-io/k3s/pkg/cli/server/server.go:478\ngithub.com/k3s-io/k3s/pkg/cli/server.Run\n\t/go/src/github.com/k3s-io/k3s/pkg/cli/server/server.go:41\ngithub.com/urfave/cli.HandleAction\n\t/go/pkg/mod/github.com/urfave/cli@v1.22.14/app.go:524\ngithub.com/urfave/cli.Command.Run\n\t/go/pkg/mod/github.com/urfave/cli@v1.22.14/command.go:175\ngithub.com/urfave/cli.(*App).Run\n\t/go/pkg/mod/github.com/urfave/cli@v1.22.14/app.go:277\nmain.main\n\t/go/src/github.com/k3s-io/k3s/cmd/server/main.go:81\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
{"level":"info","ts":"2023-10-28T21:48:12.763599Z","caller":"membership/store.go:141","msg":"Trimming membership information from the backend..."}
{"level":"info","ts":"2023-10-28T21:48:12.778274Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"378de42fe12bc35","local-member-id":"0","added-peer-id":"68b452179016861","added-peer-peer-urls":["https://1-1-2-2:2380"]}
{"level":"info","ts":"2023-10-28T21:48:12.790903Z","caller":"snapshot/v3_snapshot.go:269","msg":"restored snapshot","path":"/var/lib/rancher/k3s/server/db/snapshots/on-demand-ip-4-4-4-4-1698529562","wal-dir":"/var/lib/rancher/k3s/server/db/etcd/member/wal","data-dir":"/var/lib/rancher/k3s/server/db/etcd","snap-dir":"/var/lib/rancher/k3s/server/db/etcd/member/snap"}
time="2023-10-28T21:48:12Z" level=info msg="Starting etcd for new cluster"
{"level":"info","ts":"2023-10-28T21:48:12.791975Z","caller":"embed/etcd.go:127","msg":"configuring peer listeners","listen-peer-urls":["https://127.0.0.1:2380"]}
{"level":"info","ts":"2023-10-28T21:48:12.792017Z","caller":"embed/etcd.go:495","msg":"starting with peer TLS","tls-info":"cert = /var/lib/rancher/k3s/server/tls/etcd/peer-server-client.crt, key = /var/lib/rancher/k3s/server/tls/etcd/peer-server-client.key, client-cert=, client-key=, trusted-ca = /var/lib/rancher/k3s/server/tls/etcd/peer-ca.crt, client-cert-auth = true, crl-file = ","cipher-suites":[]}
{"level":"info","ts":"2023-10-28T21:48:12.792372Z","caller":"embed/etcd.go:135","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]}
{"level":"info","ts":"2023-10-28T21:48:12.792501Z","caller":"embed/etcd.go:309","msg":"starting an etcd server","etcd-version":"3.5.9","git-sha":"Not provided (use ./build instead of go build)","go-version":"go1.20.10","go-os":"linux","go-arch":"amd64","max-cpu-set":2,"max-cpu-available":2,"member-initialized":true,"name":"ip-4-4-4-4-8fefaf15","data-dir":"/var/lib/rancher/k3s/server/db/etcd","wal-dir":"","wal-dir-dedicated":"","member-dir":"/var/lib/rancher/k3s/server/db/etcd/member","force-new-cluster":true,"heartbeat-interval":"500ms","election-timeout":"5s","initial-election-tick-advance":true,"snapshot-count":10000,"max-wals":5,"max-snapshots":5,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["https://1-1-2-2:2380"],"listen-peer-urls":["https://127.0.0.1:2380"],"advertise-client-urls":["https://127.0.0.1:2379"],"listen-client-urls":["https://127.0.0.1:2379"],"listen-metrics-urls":["http://127.0.0.1:2381"],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"","initial-cluster-state":"new","initial-cluster-token":"","quota-backend-bytes":2147483648,"max-request-bytes":1572864,"max-concurrent-streams":4294967295,"pre-vote":true,"initial-corrupt-check":true,"corrupt-check-time-interval":"0s","compact-check-time-enabled":false,"compact-check-time-interval":"1m0s","auto-compaction-mode":"","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":"","downgrade-check-interval":"5s"}
{"level":"info","ts":"2023-10-28T21:48:12.793899Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","took":"1.200927ms"}
{"level":"info","ts":"2023-10-28T21:48:12.794415Z","caller":"etcdserver/server.go:509","msg":"recovered v2 store from snapshot","snapshot-index":1,"snapshot-size":"6.5 kB"}
{"level":"info","ts":"2023-10-28T21:48:12.794451Z","caller":"etcdserver/server.go:522","msg":"recovered v3 backend from snapshot","backend-size-bytes":4325376,"backend-size":"4.3 MB","backend-size-in-use-bytes":4304896,"backend-size-in-use":"4.3 MB"}
{"level":"info","ts":"2023-10-28T21:48:12.794887Z","caller":"etcdserver/raft.go:603","msg":"forcing restart member","cluster-id":"378de42fe12bc35","local-member-id":"68b452179016861","commit-index":1}
{"level":"info","ts":"2023-10-28T21:48:12.794935Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 switched to configuration voters=(471546596056721505)"}
{"level":"info","ts":"2023-10-28T21:48:12.794964Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became follower at term 1"}
{"level":"info","ts":"2023-10-28T21:48:12.794979Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 68b452179016861 [peers: [68b452179016861], term: 1, commit: 1, applied: 1, lastindex: 1, lastterm: 1]"}
{"level":"info","ts":"2023-10-28T21:48:12.795046Z","caller":"membership/cluster.go:278","msg":"recovered/added member from store","cluster-id":"378de42fe12bc35","local-member-id":"68b452179016861","recovered-remote-peer-id":"68b452179016861","recovered-remote-peer-urls":["https://1-1-2-2:2380"]}
{"level":"warn","ts":"2023-10-28T21:48:12.796091Z","caller":"auth/store.go:1238","msg":"simple token is not cryptographically signed"}
{"level":"info","ts":"2023-10-28T21:48:12.80107Z","caller":"mvcc/kvstore.go:393","msg":"kvstore restored","current-rev":2255}
{"level":"info","ts":"2023-10-28T21:48:12.804166Z","caller":"etcdserver/corrupt.go:95","msg":"starting initial corruption check","local-member-id":"68b452179016861","timeout":"15s"}
{"level":"info","ts":"2023-10-28T21:48:12.80516Z","caller":"etcdserver/corrupt.go:165","msg":"initial corruption checking passed; no corruption","local-member-id":"68b452179016861"}
{"level":"info","ts":"2023-10-28T21:48:12.805295Z","caller":"etcdserver/server.go:854","msg":"starting etcd server","local-member-id":"68b452179016861","local-server-version":"3.5.9","cluster-version":"to_be_decided"}
{"level":"info","ts":"2023-10-28T21:48:12.805475Z","caller":"etcdserver/server.go:738","msg":"started as single-node; fast-forwarding election ticks","local-member-id":"68b452179016861","forward-ticks":9,"forward-duration":"4.5s","election-ticks":10,"election-timeout":"5s"}
{"level":"info","ts":"2023-10-28T21:48:12.80564Z","caller":"fileutil/purge.go:44","msg":"started to purge file","dir":"/var/lib/rancher/k3s/server/db/etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"}
{"level":"info","ts":"2023-10-28T21:48:12.805716Z","caller":"fileutil/purge.go:44","msg":"started to purge file","dir":"/var/lib/rancher/k3s/server/db/etcd/member/snap","suffix":"snap","max":5,"interval":"30s"}
{"level":"info","ts":"2023-10-28T21:48:12.80577Z","caller":"fileutil/purge.go:44","msg":"started to purge file","dir":"/var/lib/rancher/k3s/server/db/etcd/member/wal","suffix":"wal","max":5,"interval":"30s"}
{"level":"info","ts":"2023-10-28T21:48:12.806265Z","caller":"embed/etcd.go:726","msg":"starting with client TLS","tls-info":"cert = /var/lib/rancher/k3s/server/tls/etcd/server-client.crt, key = /var/lib/rancher/k3s/server/tls/etcd/server-client.key, client-cert=, client-key=, trusted-ca = /var/lib/rancher/k3s/server/tls/etcd/server-ca.crt, client-cert-auth = true, crl-file = ","cipher-suites":[]}
{"level":"info","ts":"2023-10-28T21:48:12.806391Z","caller":"embed/etcd.go:597","msg":"serving peer traffic","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T21:48:12.806452Z","caller":"embed/etcd.go:569","msg":"cmux::serve","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T21:48:12.806499Z","caller":"embed/etcd.go:278","msg":"now serving peer/client/metrics","local-member-id":"68b452179016861","initial-advertise-peer-urls":["https://1-1-2-2:2380"],"listen-peer-urls":["https://127.0.0.1:2380"],"advertise-client-urls":["https://127.0.0.1:2379"],"listen-client-urls":["https://127.0.0.1:2379"],"listen-metrics-urls":["http://127.0.0.1:2381"]}
{"level":"info","ts":"2023-10-28T21:48:12.807044Z","caller":"embed/etcd.go:855","msg":"serving metrics","address":"http://127.0.0.1:2381"}
time="2023-10-28T21:48:13Z" level=info msg="Running cloud-controller-manager --allocate-node-cidrs=true --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --authorization-kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --bind-address=127.0.0.1 --cloud-config=/var/lib/rancher/k3s/server/etc/cloud-config.yaml --cloud-provider=k3s --cluster-cidr=10.42.0.0/16 --configure-cloud-routes=false --controllers=*,-route,-cloud-node,-cloud-node-lifecycle --kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --leader-elect-resource-name=k3s-cloud-controller-manager --node-status-update-frequency=1m0s --profiling=false --secure-port=0"
time="2023-10-28T21:48:13Z" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token"
time="2023-10-28T21:48:13Z" level=info msg="To join server node to cluster: k3s server -s https://1-1-2-2:6443 -t ${SERVER_NODE_TOKEN}"
time="2023-10-28T21:48:13Z" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token"
time="2023-10-28T21:48:13Z" level=info msg="To join agent node to cluster: k3s agent -s https://1-1-2-2:6443 -t ${AGENT_NODE_TOKEN}"
time="2023-10-28T21:48:13Z" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml"
time="2023-10-28T21:48:13Z" level=info msg="Run: k3s kubectl"
time="2023-10-28T21:48:13Z" level=warning msg="remove /var/lib/rancher/k3s/agent/etc/k3s-agent-load-balancer.json: no such file or directory"
time="2023-10-28T21:48:13Z" level=info msg="Adding server to load balancer k3s-agent-load-balancer: 127.0.0.1:6443"
time="2023-10-28T21:48:13Z" level=info msg="Running load balancer k3s-agent-load-balancer 127.0.0.1:6444 -> [127.0.0.1:6443] [default: 127.0.0.1:6443]"
time="2023-10-28T21:48:13Z" level=info msg="Cluster-Http-Server 2023/10/28 21:48:13 http: TLS handshake error from 127.0.0.1:39062: remote error: tls: bad certificate"
time="2023-10-28T21:48:13Z" level=info msg="Cluster-Http-Server 2023/10/28 21:48:13 http: TLS handshake error from 127.0.0.1:39088: remote error: tls: bad certificate"
time="2023-10-28T21:48:14Z" level=debug msg="Tunnel server handing HTTP/1.1 GET request for /v1-k3s/connect from 18.221.175.196:57406"
time="2023-10-28T21:48:14Z" level=info msg="Handling backend connection request [ip-1-1-1-1]"
time="2023-10-28T21:48:14Z" level=info msg="Password verified locally for node ip-4-4-4-4"
time="2023-10-28T21:48:14Z" level=info msg="certificate CN=ip-4-4-4-4 signed by CN=k3s-server-ca@1698529279: notBefore=2023-10-28 21:41:19 +0000 UTC notAfter=2024-10-27 21:48:14 +0000 UTC"
time="2023-10-28T21:48:14Z" level=info msg="certificate CN=system:node:ip-4-4-4-4,O=system:nodes signed by CN=k3s-client-ca@1698529279: notBefore=2023-10-28 21:41:19 +0000 UTC notAfter=2024-10-27 21:48:14 +0000 UTC"
{"level":"info","ts":"2023-10-28T21:48:17.79519Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 is starting a new election at term 1"}
{"level":"info","ts":"2023-10-28T21:48:17.795256Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became pre-candidate at term 1"}
{"level":"info","ts":"2023-10-28T21:48:17.795624Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 received MsgPreVoteResp from 68b452179016861 at term 1"}
{"level":"info","ts":"2023-10-28T21:48:17.795644Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became candidate at term 2"}
{"level":"info","ts":"2023-10-28T21:48:17.795655Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 received MsgVoteResp from 68b452179016861 at term 2"}
{"level":"info","ts":"2023-10-28T21:48:17.795669Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became leader at term 2"}
{"level":"info","ts":"2023-10-28T21:48:17.79568Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 68b452179016861 elected leader 68b452179016861 at term 2"}
{"level":"info","ts":"2023-10-28T21:48:17.797995Z","caller":"etcdserver/server.go:2064","msg":"published local member to cluster through raft","local-member-id":"68b452179016861","local-member-attributes":"{Name:ip-4-4-4-4-8fefaf15 ClientURLs:[https://127.0.0.1:2379]}","request-path":"/0/members/68b452179016861/attributes","cluster-id":"378de42fe12bc35","publish-timeout":"15s"}
{"level":"info","ts":"2023-10-28T21:48:17.798134Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T21:48:17.798371Z","caller":"etcdserver/server.go:2573","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"}
{"level":"info","ts":"2023-10-28T21:48:17.79913Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T21:48:17.800518Z","caller":"embed/serve.go:250","msg":"serving client traffic securely","traffic":"grpc","address":"127.0.0.1:2379"}
{"level":"info","ts":"2023-10-28T21:48:17.801469Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"378de42fe12bc35","local-member-id":"68b452179016861","cluster-version":"3.5"}
{"level":"info","ts":"2023-10-28T21:48:17.801653Z","caller":"etcdserver/server.go:2597","msg":"cluster version is updated","cluster-version":"3.5"}
{"level":"info","ts":"2023-10-28T21:48:17.802195Z","caller":"embed/serve.go:250","msg":"serving client traffic securely","traffic":"http","address":"127.0.0.1:2382"}
time="2023-10-28T21:48:17Z" level=info msg="Defragmenting etcd database"
{"level":"info","ts":"2023-10-28T21:48:17.825243Z","caller":"v3rpc/maintenance.go:90","msg":"starting defragment"}
{"level":"info","ts":"2023-10-28T21:48:17.831403Z","caller":"backend/backend.go:497","msg":"defragmenting","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","current-db-size-bytes":4325376,"current-db-size":"4.3 MB","current-db-size-in-use-bytes":4308992,"current-db-size-in-use":"4.3 MB"}
{"level":"info","ts":"2023-10-28T21:48:17.925459Z","caller":"backend/backend.go:549","msg":"finished defragmenting directory","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","current-db-size-bytes-diff":-212992,"current-db-size-bytes":4112384,"current-db-size":"4.1 MB","current-db-size-in-use-bytes-diff":-204800,"current-db-size-in-use-bytes":4104192,"current-db-size-in-use":"4.1 MB","took":"100.084088ms"}
{"level":"info","ts":"2023-10-28T21:48:17.925521Z","caller":"v3rpc/maintenance.go:96","msg":"finished defragment"}
time="2023-10-28T21:48:17Z" level=info msg="etcd data store connection OK"
time="2023-10-28T21:48:17Z" level=info msg="Waiting for API server to become available"
time="2023-10-28T21:48:17Z" level=info msg="Saving cluster bootstrap data to datastore"
time="2023-10-28T21:48:17Z" level=info msg="ETCD server is now running"
time="2023-10-28T21:48:17Z" level=info msg="k3s is up and running"
time="2023-10-28T21:48:17Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T21:48:17Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T21:48:17Z" level=warning msg="Bootstrap key already exists"
time="2023-10-28T21:48:20Z" level=info msg="Defragmenting etcd database"
{"level":"info","ts":"2023-10-28T21:48:20.252692Z","caller":"v3rpc/maintenance.go:90","msg":"starting defragment"}
{"level":"info","ts":"2023-10-28T21:48:20.256066Z","caller":"backend/backend.go:497","msg":"defragmenting","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","current-db-size-bytes":4112384,"current-db-size":"4.1 MB","current-db-size-in-use-bytes":4104192,"current-db-size-in-use":"4.1 MB"}
{"level":"info","ts":"2023-10-28T21:48:20.344135Z","caller":"backend/backend.go:549","msg":"finished defragmenting directory","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","current-db-size-bytes-diff":0,"current-db-size-bytes":4112384,"current-db-size":"4.1 MB","current-db-size-in-use-bytes-diff":0,"current-db-size-in-use-bytes":4104192,"current-db-size-in-use":"4.1 MB","took":"91.32874ms"}
{"level":"info","ts":"2023-10-28T21:48:20.344542Z","caller":"v3rpc/maintenance.go:96","msg":"finished defragment"}
time="2023-10-28T21:48:20Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T21:48:20Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T21:48:20Z" level=info msg="Reconciling bootstrap data between datastore and disk"
time="2023-10-28T21:48:20Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T21:48:20Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling RequestHeaderCAKey at '/var/lib/rancher/k3s/server/tls/request-header-ca.key'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling ServerCA at '/var/lib/rancher/k3s/server/tls/server-ca.crt'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling ServiceKey at '/var/lib/rancher/k3s/server/tls/service.key'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling ETCDServerCA at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.crt'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling ETCDServerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.key'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling IPSECKey at '/var/lib/rancher/k3s/server/cred/ipsec.psk'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling PasswdFile at '/var/lib/rancher/k3s/server/cred/passwd'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling RequestHeaderCA at '/var/lib/rancher/k3s/server/tls/request-header-ca.crt'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling ClientCA at '/var/lib/rancher/k3s/server/tls/client-ca.crt'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling ClientCAKey at '/var/lib/rancher/k3s/server/tls/client-ca.key'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling ETCDPeerCA at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.crt'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling ETCDPeerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.key'"
time="2023-10-28T21:48:20Z" level=debug msg="Reconciling ServerCAKey at '/var/lib/rancher/k3s/server/tls/server-ca.key'"
time="2023-10-28T21:48:20Z" level=info msg="Cluster reset: backing up certificates directory to /var/lib/rancher/k3s/server/tls-1698529700"
time="2023-10-28T21:48:20Z" level=warning msg="Updating bootstrap data on disk from datastore"
time="2023-10-28T21:48:20Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1698529279: notBefore=2023-10-28 21:41:19 +0000 UTC notAfter=2024-10-27 21:48:20 +0000 UTC"
time="2023-10-28T21:48:20Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1698529279: notBefore=2023-10-28 21:41:19 +0000 UTC notAfter=2024-10-27 21:48:20 +0000 UTC"
time="2023-10-28T21:48:20Z" level=info msg="stopping etcd"
{"level":"info","ts":"2023-10-28T21:48:20.400382Z","caller":"embed/etcd.go:376","msg":"closing etcd server","name":"ip-4-4-4-4-8fefaf15","data-dir":"/var/lib/rancher/k3s/server/db/etcd","advertise-peer-urls":["https://1-1-2-2:2380"],"advertise-client-urls":["https://127.0.0.1:2379"]}
{"level":"info","ts":"2023-10-28T21:48:20.403702Z","caller":"etcdserver/server.go:1465","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"68b452179016861","current-leader-member-id":"68b452179016861"}
{"level":"info","ts":"2023-10-28T21:48:20.41085Z","caller":"embed/etcd.go:579","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T21:48:20.410968Z","caller":"embed/etcd.go:584","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T21:48:20.410983Z","caller":"embed/etcd.go:378","msg":"closed etcd server","name":"ip-4-4-4-4-8fefaf15","data-dir":"/var/lib/rancher/k3s/server/db/etcd","advertise-peer-urls":["https://1-1-2-2:2380"],"advertise-client-urls":["https://127.0.0.1:2379"]}
time="2023-10-28T21:48:25Z" level=info msg="Managed etcd cluster membership has been reset, restart without --cluster-reset flag now. Backup and delete ${datadir}/server/db on each peer etcd server and rejoin the nodes"K3S Cluster Status:
$ sudo /usr/local/bin/kubectl --kubeconfig /etc/rancher/k3s/k3s.yaml get nodes
NAME STATUS ROLES AGE VERSION
ip-1-1-1-1 Ready <none> 23m v1.26.10-rc2+k3s1
ip-2-2-2-2 Ready control-plane,etcd,master 25m v1.26.10-rc2+k3s1
ip-3-3-3-3 Ready control-plane,etcd,master 24m v1.26.10-rc2+k3s1
ip-4-4-4-4 Ready control-plane,etcd,master 26m v1.26.10-rc2+k3s1
======= Execute DONE ========
======= Execute START ========
$ sudo /usr/local/bin/kubectl --kubeconfig /etc/rancher/k3s/k3s.yaml get pods -A
NAMESPACE NAME READY STATUS RESTARTS AGE
auto-clusterip test-clusterip-5f695f5786-ldwtt 1/1 Running 0 22m
auto-clusterip test-clusterip-5f695f5786-vzzm6 1/1 Running 1 (17m ago) 22m
auto-daemonset test-daemonset-6gkh5 1/1 Running 0 22m
auto-daemonset test-daemonset-9t5dt 1/1 Running 1 (16m ago) 22m
auto-daemonset test-daemonset-bzvxf 1/1 Running 0 22m
auto-daemonset test-daemonset-nskxh 1/1 Running 1 (17m ago) 22m
auto-dns dnsutils 1/1 Running 1 (16m ago) 22m
auto-ingress test-ingress-6q9c4 1/1 Running 1 (16m ago) 22m
auto-ingress test-ingress-x4vcm 1/1 Running 1 (17m ago) 22m
auto-nodeport test-nodeport-6db7c7d54-5fltx 1/1 Running 1 (16m ago) 22m
auto-nodeport test-nodeport-6db7c7d54-ssk9f 1/1 Running 0 22m
clusterip clusterip-pod-demo 1/1 Running 0 22m
clusterip clusterip-pod-demo-2 1/1 Running 1 (17m ago) 22m
clusterip clusterip-pod-demo-3 1/1 Running 1 (16m ago) 22m
default clusterip-pod-demo 1/1 Running 1 (17m ago) 22m
default clusterip-pod-demo-2 1/1 Running 0 22m
default clusterip-pod-demo-3 1/1 Running 1 (16m ago) 22m
kube-system coredns-59b4f5bbd5-dhz5m 1/1 Running 0 26m
kube-system helm-install-traefik-crd-pncv9 0/1 Completed 0 26m
kube-system helm-install-traefik-kdfgt 0/1 Completed 1 26m
kube-system local-path-provisioner-76d776f6f9-c2szh 1/1 Running 0 26m
kube-system metrics-server-68cf49699b-2mbdw 1/1 Running 0 26m
kube-system svclb-traefik-81dfbde1-lcvh7 2/2 Running 0 25m
kube-system svclb-traefik-81dfbde1-qs6px 2/2 Running 0 24m
kube-system svclb-traefik-81dfbde1-qvzdf 2/2 Running 2 (17m ago) 25m
kube-system svclb-traefik-81dfbde1-tb7l9 2/2 Running 2 (16m ago) 24m
kube-system traefik-f75d47c4b-zfznz 1/1 Running 0 25m
Backport fix for Cluster Restore for s3 snapshot fails
8727