search

k3s-io / k3s

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

Cluster Restore for s3 snapshot fails #8727

Closed aganesh-suse closed 10 months ago

aganesh-suse commented 10 months ago

Environmental Info: K3s Version: 

 $ k3s -v 
k3s version v1.28.3-rc1+k3s1 (6aef26e9)
go version go1.20.10

Node(s) CPU architecture, OS, and Version: 

$ cat /etc/os-release
PRETTY_NAME="Ubuntu 22.04.2 LTS"
$ uname -m
x86_64

Cluster Configuration:

HA: 3 server/ 1 agent Describe the bug:

Restore k3s cluster from s3 snapshot fails.

Steps To Reproduce:

The last lines are on repeat for over 15 minutes, at which point I exit the command.

Expected behavior:

Cluster should be restorable from s3 snapshot.

Actual behavior:

Unable to restore k3s cluster from s3 snapshot.

Additional context / logs:

Restore operation works from a local snapshot. The foll cmd succeeds. Ex: 

sudo
k3s server --cluster-reset
--cluster-reset-restore-path=/var/lib/rancher/k3s/server/db/snapshots/on-demand-ip-172-31-18-195-1698346321
--debug
aganesh-suse commented 10 months ago

Validated on master branch with version v1.28.3-rc2+k3s1

Environment Details

Infrastructure

Node(s) CPU architecture, OS, and Version:

$ cat /etc/os-release
PRETTY_NAME="Ubuntu 22.04.2 LTS"

$ uname -m
x86_64

Cluster Configuration:

HA: 3 server/ 1 agent

Config.yaml:

token: xxxx
cluster-init: true
write-kubeconfig-mode: "0644"
node-external-ip: 1.1.1.1
node-label:
- k3s-upgrade=server

Testing Steps

  1. Copy config.yaml 
    $ sudo mkdir -p /etc/rancher/k3s && sudo cp config.yaml /etc/rancher/k3s
  2. Install k3s 
    curl -sfL https://get.k3s.io | sudo INSTALL_K3S_VERSION='v1.28.3-rc2+k3s1' sh -s - server
  3. Verify Cluster Status: 
    kubectl get nodes -o wide
kubectl get pods -A
  4. Apply some workloads
  5. 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"
  6. Kill servers 2 and 3: 
    sudo k3s-killall.sh
  7. Stop k3s server on server1 
    sudo systemctl stop k3s
  8. Run cluster reset from s3 snapshot saved: 
    sudo k3s server --cluster-reset --etcd-s3   --cluster-reset-restore-path=on-demand-ip-172-31-22-217-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
  9. Start k3s services on servers 1, 2 and 3: 
    sudo systemctl start k3s
  10. 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:

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-28T17:34:29Z" level=warning msg="remove /var/lib/rancher/k3s/agent/etc/k3s-agent-load-balancer.json: no such file or directory"
time="2023-10-28T17:34:29Z" 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-28T17:34:29Z" level=info msg="Starting k3s v1.28.3-rc2+k3s1 (49411e70)"
time="2023-10-28T17:34:29Z" level=info msg="Managed etcd cluster bootstrap already complete and initialized"
time="2023-10-28T17:34:29Z" level=info msg="Starting temporary etcd to reconcile with datastore"
{"level":"info","ts":"2023-10-28T17:34:29.335932Z","caller":"embed/etcd.go:127","msg":"configuring peer listeners","listen-peer-urls":["http://127.0.0.1:2400"]}
{"level":"info","ts":"2023-10-28T17:34:29.336726Z","caller":"embed/etcd.go:135","msg":"configuring client listeners","listen-client-urls":["http://127.0.0.1:2399"]}
{"level":"info","ts":"2023-10-28T17:34:29.337072Z","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-f61ec646","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-28T17:34:29.339333Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"/var/lib/rancher/k3s/server/db/etcd-tmp/member/snap/db","took":"1.991763ms"}
{"level":"info","ts":"2023-10-28T17:34:29.34644Z","caller":"etcdserver/server.go:530","msg":"No snapshot found. Recovering WAL from scratch!"}
{"level":"info","ts":"2023-10-28T17:34:29.376267Z","caller":"etcdserver/raft.go:573","msg":"discarding uncommitted WAL entries","entry-index":2460,"commit-index-from-wal":2459,"number-of-discarded-entries":4}
{"level":"info","ts":"2023-10-28T17:34:29.38864Z","caller":"etcdserver/raft.go:603","msg":"forcing restart member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","commit-index":2461}
{"level":"info","ts":"2023-10-28T17:34:29.388861Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=()"}
{"level":"info","ts":"2023-10-28T17:34:29.388897Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became follower at term 3"}
{"level":"info","ts":"2023-10-28T17:34:29.388914Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft a8142d3343e761f [peers: [], term: 3, commit: 2461, applied: 0, lastindex: 2461, lastterm: 3]"}
{"level":"warn","ts":"2023-10-28T17:34:29.423945Z","caller":"auth/store.go:1238","msg":"simple token is not cryptographically signed"}
{"level":"info","ts":"2023-10-28T17:34:29.435449Z","caller":"mvcc/kvstore.go:393","msg":"kvstore restored","current-rev":2227}
{"level":"info","ts":"2023-10-28T17:34:29.437109Z","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-28T17:34:29.440389Z","caller":"etcdserver/corrupt.go:95","msg":"starting initial corruption check","local-member-id":"a8142d3343e761f","timeout":"15s"}
{"level":"info","ts":"2023-10-28T17:34:29.441873Z","caller":"etcdserver/corrupt.go:165","msg":"initial corruption checking passed; no corruption","local-member-id":"a8142d3343e761f"}
{"level":"info","ts":"2023-10-28T17:34:29.441917Z","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-28T17:34:29.442152Z","caller":"etcdserver/server.go:754","msg":"starting initial election tick advance","election-ticks":10}
{"level":"info","ts":"2023-10-28T17:34:29.442486Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359)"}
{"level":"info","ts":"2023-10-28T17:34:29.442585Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","added-peer-id":"a8142d3343e761f","added-peer-peer-urls":["https://172.31.28.17:2380"]}
{"level":"info","ts":"2023-10-28T17:34:29.442709Z","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-28T17:34:29.442777Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"}
{"level":"info","ts":"2023-10-28T17:34:29.445263Z","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-28T17:34:29.44801Z","caller":"embed/etcd.go:597","msg":"serving peer traffic","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T17:34:29.448046Z","caller":"embed/etcd.go:569","msg":"cmux::serve","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T17:34:29.449362Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359) learners=(15893888857076234589)"}
{"level":"info","ts":"2023-10-28T17:34:29.449638Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","added-peer-id":"dc926fb4c191795d","added-peer-peer-urls":["https://172.31.25.138:2380"]}
{"level":"info","ts":"2023-10-28T17:34:29.449786Z","caller":"rafthttp/peer.go:133","msg":"starting remote peer","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.450008Z","caller":"rafthttp/pipeline.go:72","msg":"started HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.454582Z","caller":"rafthttp/peer.go:137","msg":"started remote peer","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.454711Z","caller":"rafthttp/transport.go:317","msg":"added remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"dc926fb4c191795d","remote-peer-urls":["https://172.31.25.138:2380"]}
{"level":"info","ts":"2023-10-28T17:34:29.455654Z","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":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.455965Z","caller":"rafthttp/stream.go:395","msg":"started stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.456448Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 15893888857076234589)"}
{"level":"info","ts":"2023-10-28T17:34:29.456501Z","caller":"membership/cluster.go:535","msg":"promote member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f"}
{"level":"info","ts":"2023-10-28T17:34:29.455441Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.455474Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.459942Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 15893888857076234589) learners=(8426863607651721669)"}
{"level":"info","ts":"2023-10-28T17:34:29.46001Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","added-peer-id":"74f23bcdc0bf61c5","added-peer-peer-urls":["https://172.31.26.211:2380"]}
{"level":"info","ts":"2023-10-28T17:34:29.460052Z","caller":"rafthttp/peer.go:133","msg":"starting remote peer","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.460091Z","caller":"rafthttp/pipeline.go:72","msg":"started HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.460927Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.461154Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.461359Z","caller":"rafthttp/peer.go:137","msg":"started remote peer","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.461383Z","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":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.461441Z","caller":"rafthttp/transport.go:317","msg":"added remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"74f23bcdc0bf61c5","remote-peer-urls":["https://172.31.26.211:2380"]}
{"level":"info","ts":"2023-10-28T17:34:29.461672Z","caller":"rafthttp/stream.go:395","msg":"started stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.461695Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 8426863607651721669 15893888857076234589)"}
{"level":"info","ts":"2023-10-28T17:34:29.461729Z","caller":"membership/cluster.go:535","msg":"promote member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f"}
{"level":"info","ts":"2023-10-28T17:34:29.467574Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 15893888857076234589)"}
{"level":"info","ts":"2023-10-28T17:34:29.467699Z","caller":"membership/cluster.go:472","msg":"removed member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"74f23bcdc0bf61c5","removed-remote-peer-urls":["https://172.31.26.211:2380"]}
{"level":"info","ts":"2023-10-28T17:34:29.467722Z","caller":"rafthttp/peer.go:330","msg":"stopping remote peer","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.46775Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.467784Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.467856Z","caller":"rafthttp/pipeline.go:85","msg":"stopped HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.467881Z","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":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.46793Z","caller":"rafthttp/stream.go:442","msg":"stopped stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.46795Z","caller":"rafthttp/peer.go:335","msg":"stopped remote peer","remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.467968Z","caller":"rafthttp/transport.go:355","msg":"removed remote peer","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"74f23bcdc0bf61c5"}
{"level":"info","ts":"2023-10-28T17:34:29.46809Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359)"}
{"level":"info","ts":"2023-10-28T17:34:29.468159Z","caller":"membership/cluster.go:472","msg":"removed member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"dc926fb4c191795d","removed-remote-peer-urls":["https://172.31.25.138:2380"]}
{"level":"info","ts":"2023-10-28T17:34:29.468179Z","caller":"rafthttp/peer.go:330","msg":"stopping remote peer","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.468195Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.468224Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.46826Z","caller":"rafthttp/pipeline.go:85","msg":"stopped HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.468284Z","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":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.468522Z","caller":"rafthttp/stream.go:442","msg":"stopped stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.468544Z","caller":"rafthttp/peer.go:335","msg":"stopped remote peer","remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:29.468556Z","caller":"rafthttp/transport.go:355","msg":"removed remote peer","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"dc926fb4c191795d"}
{"level":"info","ts":"2023-10-28T17:34:37.889793Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f is starting a new election at term 3"}
{"level":"info","ts":"2023-10-28T17:34:37.889841Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became pre-candidate at term 3"}
{"level":"info","ts":"2023-10-28T17:34:37.88988Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f received MsgPreVoteResp from a8142d3343e761f at term 3"}
{"level":"info","ts":"2023-10-28T17:34:37.889922Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became candidate at term 4"}
{"level":"info","ts":"2023-10-28T17:34:37.889944Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f received MsgVoteResp from a8142d3343e761f at term 4"}
{"level":"info","ts":"2023-10-28T17:34:37.889979Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became leader at term 4"}
{"level":"info","ts":"2023-10-28T17:34:37.890001Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: a8142d3343e761f elected leader a8142d3343e761f at term 4"}
{"level":"info","ts":"2023-10-28T17:34:37.891298Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T17:34:37.891315Z","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-f61ec646 ClientURLs:[http://127.0.0.1:2399]}","request-path":"/0/members/a8142d3343e761f/attributes","cluster-id":"bcbdcaabf4d4714c","publish-timeout":"15s"}
{"level":"info","ts":"2023-10-28T17:34:37.891382Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T17:34:37.891685Z","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-28T17:34:37.892443Z","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-28T17:34:37Z" level=info msg="Defragmenting etcd database"
{"level":"info","ts":"2023-10-28T17:34:37.894671Z","caller":"v3rpc/maintenance.go:90","msg":"starting defragment"}
{"level":"info","ts":"2023-10-28T17:34:37.898655Z","caller":"backend/backend.go:497","msg":"defragmenting","path":"/var/lib/rancher/k3s/server/db/etcd-tmp/member/snap/db","current-db-size-bytes":4423680,"current-db-size":"4.4 MB","current-db-size-in-use-bytes":4403200,"current-db-size-in-use":"4.4 MB"}
{"level":"info","ts":"2023-10-28T17:34:37.965619Z","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":-212992,"current-db-size-bytes":4210688,"current-db-size":"4.2 MB","current-db-size-in-use-bytes-diff":-200704,"current-db-size-in-use-bytes":4202496,"current-db-size-in-use":"4.2 MB","took":"70.905259ms"}
{"level":"info","ts":"2023-10-28T17:34:37.965686Z","caller":"v3rpc/maintenance.go:96","msg":"finished defragment"}
time="2023-10-28T17:34:37Z" level=info msg="etcd temporary data store connection OK"
time="2023-10-28T17:34:37Z" level=info msg="Reconciling bootstrap data between datastore and disk"
time="2023-10-28T17:34:37Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T17:34:37Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling ClientCA at '/var/lib/rancher/k3s/server/tls/client-ca.crt'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling ETCDPeerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.key'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling PasswdFile at '/var/lib/rancher/k3s/server/cred/passwd'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling RequestHeaderCAKey at '/var/lib/rancher/k3s/server/tls/request-header-ca.key'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling ServerCA at '/var/lib/rancher/k3s/server/tls/server-ca.crt'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling ServiceKey at '/var/lib/rancher/k3s/server/tls/service.key'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling ClientCAKey at '/var/lib/rancher/k3s/server/tls/client-ca.key'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling ETCDPeerCA at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.crt'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling ETCDServerCA at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.crt'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling ETCDServerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.key'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling IPSECKey at '/var/lib/rancher/k3s/server/cred/ipsec.psk'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling RequestHeaderCA at '/var/lib/rancher/k3s/server/tls/request-header-ca.crt'"
time="2023-10-28T17:34:37Z" level=debug msg="Reconciling ServerCAKey at '/var/lib/rancher/k3s/server/tls/server-ca.key'"
time="2023-10-28T17:34:37Z" level=info msg="Cluster reset: backing up certificates directory to /var/lib/rancher/k3s/server/tls-1698514477"
time="2023-10-28T17:34:37Z" level=warning msg="Updating bootstrap data on disk from datastore"
time="2023-10-28T17:34:37Z" level=info msg="stopping etcd"
{"level":"info","ts":"2023-10-28T17:34:37.97845Z","caller":"embed/etcd.go:376","msg":"closing etcd server","name":"ip-4-4-4-4-f61ec646","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-28T17:34:37.978988Z","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-28T17:34:37Z" level=info msg="Retrieving etcd snapshot on-demand-ip-4-4-4-4-1698514340 from S3"
time="2023-10-28T17:34:37Z" level=info msg="Checking if S3 bucket xxxx exists"
{"level":"info","ts":"2023-10-28T17:34:38.003368Z","caller":"embed/etcd.go:579","msg":"stopping serving peer traffic","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T17:34:38.003749Z","caller":"embed/etcd.go:584","msg":"stopped serving peer traffic","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T17:34:38.003851Z","caller":"embed/etcd.go:378","msg":"closed etcd server","name":"ip-4-4-4-4-f61ec646","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-28T17:34:38Z" level=info msg="S3 bucket xxxx exists"
time="2023-10-28T17:34:38Z" level=debug msg="Skip setting S3 snapshot cluster ID and token during cluster-reset"
time="2023-10-28T17:34:38Z" level=debug msg="Downloading snapshot from s3://xxxx/xxxx/on-demand-ip-4-4-4-4-1698514340"
time="2023-10-28T17:34:38Z" level=debug msg="Downloading snapshot metadata from s3://xxxx/xxxx/.metadata/on-demand-ip-4-4-4-4-1698514340"
time="2023-10-28T17:34:38Z" level=info msg="S3 download complete for /var/lib/rancher/k3s/server/db/snapshots/on-demand-ip-4-4-4-4-1698514340"
time="2023-10-28T17:34:38Z" level=info msg="Pre-restore etcd database moved to /var/lib/rancher/k3s/server/db/etcd-old-1698514478"
{"level":"info","ts":"2023-10-28T17:34:38.18255Z","caller":"snapshot/v3_snapshot.go:248","msg":"restoring snapshot","path":"/var/lib/rancher/k3s/server/db/snapshots/on-demand-ip-4-4-4-4-1698514340","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:273\ngithub.com/k3s-io/k3s/pkg/daemons/control.Server\n\t/go/src/github.com/k3s-io/k3s/pkg/daemons/control/server.go:35\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-28T17:34:38.20129Z","caller":"membership/store.go:141","msg":"Trimming membership information from the backend..."}
{"level":"info","ts":"2023-10-28T17:34:38.214382Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"378de42fe12bc35","local-member-id":"0","added-peer-id":"68b452179016861","added-peer-peer-urls":["https://172.31.28.17:2380"]}
{"level":"info","ts":"2023-10-28T17:34:38.228002Z","caller":"snapshot/v3_snapshot.go:269","msg":"restored snapshot","path":"/var/lib/rancher/k3s/server/db/snapshots/on-demand-ip-4-4-4-4-1698514340","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-28T17:34:38Z" level=info msg="Starting etcd for new cluster"
{"level":"info","ts":"2023-10-28T17:34:38.229262Z","caller":"embed/etcd.go:127","msg":"configuring peer listeners","listen-peer-urls":["https://127.0.0.1:2380"]}
{"level":"info","ts":"2023-10-28T17:34:38.229499Z","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-28T17:34:38.229795Z","caller":"embed/etcd.go:135","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]}
{"level":"info","ts":"2023-10-28T17:34:38.229928Z","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-a778973d","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://172.31.28.17: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-28T17:34:38.231241Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","took":"1.063411ms"}
{"level":"info","ts":"2023-10-28T17:34:38.231891Z","caller":"etcdserver/server.go:509","msg":"recovered v2 store from snapshot","snapshot-index":1,"snapshot-size":"6.5 kB"}
{"level":"info","ts":"2023-10-28T17:34:38.231927Z","caller":"etcdserver/server.go:522","msg":"recovered v3 backend from snapshot","backend-size-bytes":4042752,"backend-size":"4.0 MB","backend-size-in-use-bytes":4018176,"backend-size-in-use":"4.0 MB"}
{"level":"info","ts":"2023-10-28T17:34:38.232349Z","caller":"etcdserver/raft.go:603","msg":"forcing restart member","cluster-id":"378de42fe12bc35","local-member-id":"68b452179016861","commit-index":1}
{"level":"info","ts":"2023-10-28T17:34:38.232394Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 switched to configuration voters=(471546596056721505)"}
{"level":"info","ts":"2023-10-28T17:34:38.232421Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became follower at term 1"}
{"level":"info","ts":"2023-10-28T17:34:38.23245Z","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-28T17:34:38.232523Z","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://172.31.28.17:2380"]}
{"level":"warn","ts":"2023-10-28T17:34:38.233168Z","caller":"auth/store.go:1238","msg":"simple token is not cryptographically signed"}
{"level":"info","ts":"2023-10-28T17:34:38.23696Z","caller":"mvcc/kvstore.go:393","msg":"kvstore restored","current-rev":1959}
{"level":"info","ts":"2023-10-28T17:34:38.239942Z","caller":"etcdserver/corrupt.go:95","msg":"starting initial corruption check","local-member-id":"68b452179016861","timeout":"15s"}
{"level":"info","ts":"2023-10-28T17:34:38.240854Z","caller":"etcdserver/corrupt.go:165","msg":"initial corruption checking passed; no corruption","local-member-id":"68b452179016861"}
{"level":"info","ts":"2023-10-28T17:34:38.240902Z","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-28T17:34:38.2411Z","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-28T17:34:38.241266Z","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-28T17:34:38.241393Z","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-28T17:34:38.241461Z","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-28T17:34:38.242028Z","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-28T17:34:38.242129Z","caller":"embed/etcd.go:597","msg":"serving peer traffic","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T17:34:38.242187Z","caller":"embed/etcd.go:569","msg":"cmux::serve","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T17:34:38.242244Z","caller":"embed/etcd.go:278","msg":"now serving peer/client/metrics","local-member-id":"68b452179016861","initial-advertise-peer-urls":["https://172.31.28.17: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-28T17:34:38.242578Z","caller":"embed/etcd.go:855","msg":"serving metrics","address":"http://127.0.0.1:2381"}
time="2023-10-28T17:34:38Z" 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 --feature-gates=CloudDualStackNodeIPs=true --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-28T17:34:38Z" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token"
time="2023-10-28T17:34:38Z" level=info msg="To join server node to cluster: k3s server -s https://172.31.28.17:6443 -t ${SERVER_NODE_TOKEN}"
time="2023-10-28T17:34:38Z" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token"
time="2023-10-28T17:34:38Z" level=info msg="To join agent node to cluster: k3s agent -s https://172.31.28.17:6443 -t ${AGENT_NODE_TOKEN}"
time="2023-10-28T17:34:38Z" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml"
time="2023-10-28T17:34:38Z" level=info msg="Run: k3s kubectl"
time="2023-10-28T17:34:38Z" level=warning msg="remove /var/lib/rancher/k3s/agent/etc/k3s-agent-load-balancer.json: no such file or directory"
time="2023-10-28T17:34:38Z" level=info msg="Adding server to load balancer k3s-agent-load-balancer: 127.0.0.1:6443"
time="2023-10-28T17:34:38Z" 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-28T17:34:38Z" level=info msg="Cluster-Http-Server 2023/10/28 17:34:38 http: TLS handshake error from 127.0.0.1:33760: remote error: tls: bad certificate"
time="2023-10-28T17:34:38Z" level=info msg="Cluster-Http-Server 2023/10/28 17:34:38 http: TLS handshake error from 127.0.0.1:33790: remote error: tls: bad certificate"
time="2023-10-28T17:34:39Z" level=info msg="Password verified locally for node ip-4-4-4-4"
time="2023-10-28T17:34:39Z" level=info msg="certificate CN=ip-4-4-4-4 signed by CN=k3s-server-ca@1698514077: notBefore=2023-10-28 17:27:57 +0000 UTC notAfter=2024-10-27 17:34:39 +0000 UTC"
time="2023-10-28T17:34:40Z" level=info msg="certificate CN=system:node:ip-4-4-4-4,O=system:nodes signed by CN=k3s-client-ca@1698514077: notBefore=2023-10-28 17:27:57 +0000 UTC notAfter=2024-10-27 17:34:40 +0000 UTC"
{"level":"info","ts":"2023-10-28T17:34:41.232665Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 is starting a new election at term 1"}
{"level":"info","ts":"2023-10-28T17:34:41.232877Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became pre-candidate at term 1"}
{"level":"info","ts":"2023-10-28T17:34:41.233062Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 received MsgPreVoteResp from 68b452179016861 at term 1"}
{"level":"info","ts":"2023-10-28T17:34:41.233127Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became candidate at term 2"}
{"level":"info","ts":"2023-10-28T17:34:41.233174Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 received MsgVoteResp from 68b452179016861 at term 2"}
{"level":"info","ts":"2023-10-28T17:34:41.233236Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became leader at term 2"}
{"level":"info","ts":"2023-10-28T17:34:41.233283Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 68b452179016861 elected leader 68b452179016861 at term 2"}
{"level":"info","ts":"2023-10-28T17:34:41.236673Z","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-a778973d ClientURLs:[https://127.0.0.1:2379]}","request-path":"/0/members/68b452179016861/attributes","cluster-id":"378de42fe12bc35","publish-timeout":"15s"}
{"level":"info","ts":"2023-10-28T17:34:41.236831Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T17:34:41.237092Z","caller":"etcdserver/server.go:2573","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"}
{"level":"info","ts":"2023-10-28T17:34:41.237699Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T17:34:41.239241Z","caller":"embed/serve.go:250","msg":"serving client traffic securely","traffic":"grpc","address":"127.0.0.1:2379"}
{"level":"info","ts":"2023-10-28T17:34:41.242091Z","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-28T17:34:41.242399Z","caller":"etcdserver/server.go:2597","msg":"cluster version is updated","cluster-version":"3.5"}
{"level":"info","ts":"2023-10-28T17:34:41.243353Z","caller":"embed/serve.go:250","msg":"serving client traffic securely","traffic":"http","address":"127.0.0.1:2382"}
time="2023-10-28T17:34:41Z" level=info msg="Defragmenting etcd database"
{"level":"info","ts":"2023-10-28T17:34:41.261818Z","caller":"v3rpc/maintenance.go:90","msg":"starting defragment"}
{"level":"info","ts":"2023-10-28T17:34:41.266288Z","caller":"backend/backend.go:497","msg":"defragmenting","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","current-db-size-bytes":4042752,"current-db-size":"4.0 MB","current-db-size-in-use-bytes":4022272,"current-db-size-in-use":"4.0 MB"}
{"level":"info","ts":"2023-10-28T17:34:41.336918Z","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":-163840,"current-db-size-bytes":3878912,"current-db-size":"3.9 MB","current-db-size-in-use-bytes-diff":-151552,"current-db-size-in-use-bytes":3870720,"current-db-size-in-use":"3.9 MB","took":"74.981791ms"}
{"level":"info","ts":"2023-10-28T17:34:41.337106Z","caller":"v3rpc/maintenance.go:96","msg":"finished defragment"}
time="2023-10-28T17:34:41Z" level=info msg="etcd data store connection OK"
time="2023-10-28T17:34:41Z" level=info msg="Waiting for API server to become available"
time="2023-10-28T17:34:41Z" level=info msg="Saving cluster bootstrap data to datastore"
time="2023-10-28T17:34:41Z" level=info msg="ETCD server is now running"
time="2023-10-28T17:34:41Z" level=info msg="k3s is up and running"
time="2023-10-28T17:34:41Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T17:34:41Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T17:34:41Z" level=warning msg="Bootstrap key already exists"
time="2023-10-28T17:34:43Z" level=debug msg="Tunnel server handing HTTP/1.1 GET request for /v1-k3s/connect from 18.221.175.196:33358"
time="2023-10-28T17:34:43Z" level=info msg="Handling backend connection request [ip-1-1-1-1]"
time="2023-10-28T17:34:45Z" level=info msg="Defragmenting etcd database"
{"level":"info","ts":"2023-10-28T17:34:45.784336Z","caller":"v3rpc/maintenance.go:90","msg":"starting defragment"}
{"level":"info","ts":"2023-10-28T17:34:45.788195Z","caller":"backend/backend.go:497","msg":"defragmenting","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","current-db-size-bytes":3878912,"current-db-size":"3.9 MB","current-db-size-in-use-bytes":3870720,"current-db-size-in-use":"3.9 MB"}
{"level":"info","ts":"2023-10-28T17:34:45.859944Z","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":3878912,"current-db-size":"3.9 MB","current-db-size-in-use-bytes-diff":0,"current-db-size-in-use-bytes":3870720,"current-db-size-in-use":"3.9 MB","took":"75.455893ms"}
{"level":"info","ts":"2023-10-28T17:34:45.860059Z","caller":"v3rpc/maintenance.go:96","msg":"finished defragment"}
time="2023-10-28T17:34:45Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T17:34:45Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T17:34:45Z" level=info msg="Reconciling bootstrap data between datastore and disk"
time="2023-10-28T17:34:45Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T17:34:45Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling ClientCA at '/var/lib/rancher/k3s/server/tls/client-ca.crt'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling ClientCAKey at '/var/lib/rancher/k3s/server/tls/client-ca.key'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling ETCDPeerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.key'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling PasswdFile at '/var/lib/rancher/k3s/server/cred/passwd'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling RequestHeaderCA at '/var/lib/rancher/k3s/server/tls/request-header-ca.crt'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling ServiceKey at '/var/lib/rancher/k3s/server/tls/service.key'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling ETCDPeerCA at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.crt'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling ETCDServerCA at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.crt'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling ETCDServerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.key'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling IPSECKey at '/var/lib/rancher/k3s/server/cred/ipsec.psk'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling RequestHeaderCAKey at '/var/lib/rancher/k3s/server/tls/request-header-ca.key'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling ServerCA at '/var/lib/rancher/k3s/server/tls/server-ca.crt'"
time="2023-10-28T17:34:45Z" level=debug msg="Reconciling ServerCAKey at '/var/lib/rancher/k3s/server/tls/server-ca.key'"
time="2023-10-28T17:34:45Z" level=info msg="Cluster reset: backing up certificates directory to /var/lib/rancher/k3s/server/tls-1698514485"
time="2023-10-28T17:34:45Z" level=warning msg="Updating bootstrap data on disk from datastore"
time="2023-10-28T17:34:45Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1698514077: notBefore=2023-10-28 17:27:57 +0000 UTC notAfter=2024-10-27 17:34:45 +0000 UTC"
time="2023-10-28T17:34:45Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1698514077: notBefore=2023-10-28 17:27:57 +0000 UTC notAfter=2024-10-27 17:34:45 +0000 UTC"
time="2023-10-28T17:34:45Z" level=info msg="stopping etcd"
{"level":"info","ts":"2023-10-28T17:34:45.901559Z","caller":"embed/etcd.go:376","msg":"closing etcd server","name":"ip-4-4-4-4-a778973d","data-dir":"/var/lib/rancher/k3s/server/db/etcd","advertise-peer-urls":["https://172.31.28.17:2380"],"advertise-client-urls":["https://127.0.0.1:2379"]}
{"level":"info","ts":"2023-10-28T17:34:45.902758Z","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-28T17:34:45.909278Z","caller":"embed/etcd.go:579","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T17:34:45.909434Z","caller":"embed/etcd.go:584","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T17:34:45.909468Z","caller":"embed/etcd.go:378","msg":"closed etcd server","name":"ip-4-4-4-4-a778973d","data-dir":"/var/lib/rancher/k3s/server/db/etcd","advertise-peer-urls":["https://172.31.28.17:2380"],"advertise-client-urls":["https://127.0.0.1:2379"]}
time="2023-10-28T17:34:50Z" 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>                      27m   v1.28.3-rc2+k3s1
ip-2-2-2-2          Ready    control-plane,etcd,master   29m   v1.28.3-rc2+k3s1
ip-3-3-3-3          Ready    control-plane,etcd,master   28m   v1.28.3-rc2+k3s1
ip-4-4-4-4          Ready    control-plane,etcd,master   30m   v1.28.3-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-8496c7779d-sk82g           1/1     Running     1 (21m ago)   26m
auto-clusterip   test-clusterip-8496c7779d-tk5bn           1/1     Running     1 (5m ago)    26m
auto-daemonset   test-daemonset-4twrv                      1/1     Running     1 (5m ago)    26m
auto-daemonset   test-daemonset-ghbrn                      1/1     Running     1 (21m ago)   26m
auto-daemonset   test-daemonset-pq8j6                      1/1     Running     0             26m
auto-daemonset   test-daemonset-wp872                      1/1     Running     0             26m
auto-dns         dnsutils                                  1/1     Running     0             26m
auto-ingress     test-ingress-ln54p                        1/1     Running     1 (5m ago)    26m
auto-ingress     test-ingress-lvcc4                        1/1     Running     0             26m
auto-nodeport    test-nodeport-644767cc74-hzrtw            1/1     Running     1 (21m ago)   26m
auto-nodeport    test-nodeport-644767cc74-kmccx            1/1     Running     0             26m
clusterip        clusterip-pod-demo                        1/1     Running     1 (5m ago)    26m
clusterip        clusterip-pod-demo-2                      1/1     Running     1 (21m ago)   26m
clusterip        clusterip-pod-demo-3                      1/1     Running     1 (5m ago)    26m
default          clusterip-pod-demo                        1/1     Running     1 (21m ago)   26m
default          clusterip-pod-demo-2                      1/1     Running     1 (5m ago)    26m
default          clusterip-pod-demo-3                      1/1     Running     0             26m
kube-system      coredns-6799fbcd5-d52mm                   1/1     Running     0             29m
kube-system      helm-install-traefik-crd-5hmqr            0/1     Completed   0             29m
kube-system      helm-install-traefik-ctldc                0/1     Completed   1             29m
kube-system      local-path-provisioner-84db5d44d9-pprgk   1/1     Running     0             29m
kube-system      metrics-server-67c658944b-cfbs8           1/1     Running     0             29m
kube-system      svclb-traefik-e513a371-7hv2m              2/2     Running     2 (21m ago)   29m
kube-system      svclb-traefik-e513a371-gsp2s              2/2     Running     2 (5m ago)    28m
kube-system      svclb-traefik-e513a371-sq4lf              2/2     Running     0             29m
kube-system      svclb-traefik-e513a371-zpq7v              2/2     Running     0             27m
kube-system      traefik-55f65f58b-9nr6v                   1/1     Running     0             29m