aganesh-suse
commented
10 months ago Validated on release-1.27 branch with version v1.27.7-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.27.7-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-2-2-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.27.7-rc2+k3s1 (b6f23014) 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:26:33Z" level=warning msg="remove /var/lib/rancher/k3s/agent/etc/k3s-agent-load-balancer.json: no such file or directory"
time="2023-10-28T21:26:33Z" 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:26:33Z" level=info msg="Starting k3s v1.27.7-rc2+k3s1 (b6f23014)"
time="2023-10-28T21:26:33Z" level=info msg="Managed etcd cluster bootstrap already complete and initialized"
time="2023-10-28T21:26:33Z" level=info msg="Starting temporary etcd to reconcile with datastore"
{"level":"info","ts":"2023-10-28T21:26:33.421726Z","caller":"embed/etcd.go:127","msg":"configuring peer listeners","listen-peer-urls":["http://127.0.0.1:2400"]}
{"level":"info","ts":"2023-10-28T21:26:33.422081Z","caller":"embed/etcd.go:135","msg":"configuring client listeners","listen-client-urls":["http://127.0.0.1:2399"]}
{"level":"info","ts":"2023-10-28T21:26:33.422361Z","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-1-1-2-2-648da238","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:26:33.424733Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"/var/lib/rancher/k3s/server/db/etcd-tmp/member/snap/db","took":"2.130392ms"}
{"level":"info","ts":"2023-10-28T21:26:33.43306Z","caller":"etcdserver/server.go:530","msg":"No snapshot found. Recovering WAL from scratch!"}
{"level":"info","ts":"2023-10-28T21:26:33.464415Z","caller":"etcdserver/raft.go:573","msg":"discarding uncommitted WAL entries","entry-index":2759,"commit-index-from-wal":2758,"number-of-discarded-entries":5}
{"level":"info","ts":"2023-10-28T21:26:33.476687Z","caller":"etcdserver/raft.go:603","msg":"forcing restart member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","commit-index":2760}
{"level":"info","ts":"2023-10-28T21:26:33.477008Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=()"}
{"level":"info","ts":"2023-10-28T21:26:33.477051Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became follower at term 3"}
{"level":"info","ts":"2023-10-28T21:26:33.477074Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft a8142d3343e761f [peers: [], term: 3, commit: 2760, applied: 0, lastindex: 2760, lastterm: 3]"}
{"level":"warn","ts":"2023-10-28T21:26:33.511466Z","caller":"auth/store.go:1238","msg":"simple token is not cryptographically signed"}
{"level":"info","ts":"2023-10-28T21:26:33.517858Z","caller":"mvcc/kvstore.go:393","msg":"kvstore restored","current-rev":2531}
{"level":"info","ts":"2023-10-28T21:26:33.519259Z","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:26:33.520884Z","caller":"etcdserver/corrupt.go:95","msg":"starting initial corruption check","local-member-id":"a8142d3343e761f","timeout":"15s"}
{"level":"info","ts":"2023-10-28T21:26:33.521976Z","caller":"etcdserver/corrupt.go:165","msg":"initial corruption checking passed; no corruption","local-member-id":"a8142d3343e761f"}
{"level":"info","ts":"2023-10-28T21:26:33.522025Z","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:26:33.522346Z","caller":"etcdserver/server.go:754","msg":"starting initial election tick advance","election-ticks":10}
{"level":"info","ts":"2023-10-28T21:26:33.522958Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359)"}
{"level":"info","ts":"2023-10-28T21:26:33.523098Z","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-28T21:26:33.523255Z","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:26:33.52333Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"}
{"level":"info","ts":"2023-10-28T21:26:33.525558Z","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:26:33.5259Z","caller":"embed/etcd.go:597","msg":"serving peer traffic","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T21:26:33.525921Z","caller":"embed/etcd.go:569","msg":"cmux::serve","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T21:26:33.52881Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359) learners=(10654152808524592745)"}
{"level":"info","ts":"2023-10-28T21:26:33.528903Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","added-peer-id":"93db2787fed6b669","added-peer-peer-urls":["https://172.31.25.138:2380"]}
{"level":"info","ts":"2023-10-28T21:26:33.528944Z","caller":"rafthttp/peer.go:133","msg":"starting remote peer","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.528974Z","caller":"rafthttp/pipeline.go:72","msg":"started HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.532902Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.533104Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.533107Z","caller":"rafthttp/peer.go:137","msg":"started remote peer","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.533184Z","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":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.533248Z","caller":"rafthttp/transport.go:317","msg":"added remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"93db2787fed6b669","remote-peer-urls":["https://172.31.25.138:2380"]}
{"level":"info","ts":"2023-10-28T21:26:33.533129Z","caller":"rafthttp/stream.go:395","msg":"started stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.534963Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 10654152808524592745)"}
{"level":"info","ts":"2023-10-28T21:26:33.535051Z","caller":"membership/cluster.go:535","msg":"promote member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f"}
{"level":"info","ts":"2023-10-28T21:26:33.536357Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 10654152808524592745) learners=(9837152812240668664)"}
{"level":"info","ts":"2023-10-28T21:26:33.536408Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","added-peer-id":"8884965cfed707f8","added-peer-peer-urls":["https://172.31.26.211:2380"]}
{"level":"info","ts":"2023-10-28T21:26:33.536438Z","caller":"rafthttp/peer.go:133","msg":"starting remote peer","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.536464Z","caller":"rafthttp/pipeline.go:72","msg":"started HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.537291Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.537416Z","caller":"rafthttp/peer.go:137","msg":"started remote peer","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.537448Z","caller":"rafthttp/transport.go:317","msg":"added remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"8884965cfed707f8","remote-peer-urls":["https://172.31.26.211:2380"]}
{"level":"info","ts":"2023-10-28T21:26:33.537501Z","caller":"rafthttp/stream.go:169","msg":"started stream writer with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.537552Z","caller":"rafthttp/stream.go:395","msg":"started stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.537647Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 9837152812240668664 10654152808524592745)"}
{"level":"info","ts":"2023-10-28T21:26:33.537689Z","caller":"membership/cluster.go:535","msg":"promote member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f"}
{"level":"info","ts":"2023-10-28T21:26:33.537939Z","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":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.543597Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359 10654152808524592745)"}
{"level":"info","ts":"2023-10-28T21:26:33.543689Z","caller":"membership/cluster.go:472","msg":"removed member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"8884965cfed707f8","removed-remote-peer-urls":["https://172.31.26.211:2380"]}
{"level":"info","ts":"2023-10-28T21:26:33.543721Z","caller":"rafthttp/peer.go:330","msg":"stopping remote peer","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.543742Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.543778Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.543831Z","caller":"rafthttp/pipeline.go:85","msg":"stopped HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.543854Z","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":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.543906Z","caller":"rafthttp/stream.go:442","msg":"stopped stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.543927Z","caller":"rafthttp/peer.go:335","msg":"stopped remote peer","remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.543943Z","caller":"rafthttp/transport.go:355","msg":"removed remote peer","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"8884965cfed707f8"}
{"level":"info","ts":"2023-10-28T21:26:33.544073Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f switched to configuration voters=(756959687256995359)"}
{"level":"info","ts":"2023-10-28T21:26:33.544128Z","caller":"membership/cluster.go:472","msg":"removed member","cluster-id":"bcbdcaabf4d4714c","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"93db2787fed6b669","removed-remote-peer-urls":["https://172.31.25.138:2380"]}
{"level":"info","ts":"2023-10-28T21:26:33.544147Z","caller":"rafthttp/peer.go:330","msg":"stopping remote peer","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.544163Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.544192Z","caller":"rafthttp/stream.go:294","msg":"stopped TCP streaming connection with remote peer","stream-writer-type":"unknown stream","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.544241Z","caller":"rafthttp/pipeline.go:85","msg":"stopped HTTP pipelining with remote peer","local-member-id":"a8142d3343e761f","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.544266Z","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":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.544293Z","caller":"rafthttp/stream.go:442","msg":"stopped stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"a8142d3343e761f","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.544315Z","caller":"rafthttp/peer.go:335","msg":"stopped remote peer","remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:33.544328Z","caller":"rafthttp/transport.go:355","msg":"removed remote peer","local-member-id":"a8142d3343e761f","removed-remote-peer-id":"93db2787fed6b669"}
{"level":"info","ts":"2023-10-28T21:26:38.477993Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f is starting a new election at term 3"}
{"level":"info","ts":"2023-10-28T21:26:38.478038Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became pre-candidate at term 3"}
{"level":"info","ts":"2023-10-28T21:26:38.478096Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f received MsgPreVoteResp from a8142d3343e761f at term 3"}
{"level":"info","ts":"2023-10-28T21:26:38.478134Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became candidate at term 4"}
{"level":"info","ts":"2023-10-28T21:26:38.478157Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f received MsgVoteResp from a8142d3343e761f at term 4"}
{"level":"info","ts":"2023-10-28T21:26:38.478194Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"a8142d3343e761f became leader at term 4"}
{"level":"info","ts":"2023-10-28T21:26:38.478215Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: a8142d3343e761f elected leader a8142d3343e761f at term 4"}
{"level":"info","ts":"2023-10-28T21:26:38.481623Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T21:26:38.481645Z","caller":"etcdserver/server.go:2064","msg":"published local member to cluster through raft","local-member-id":"a8142d3343e761f","local-member-attributes":"{Name:ip-1-1-2-2-648da238 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:26:38.481668Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T21:26:38.481987Z","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:26:38.482666Z","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:26:38Z" level=info msg="Defragmenting etcd database"
{"level":"info","ts":"2023-10-28T21:26:38.485757Z","caller":"v3rpc/maintenance.go:90","msg":"starting defragment"}
{"level":"info","ts":"2023-10-28T21:26:38.489335Z","caller":"backend/backend.go:497","msg":"defragmenting","path":"/var/lib/rancher/k3s/server/db/etcd-tmp/member/snap/db","current-db-size-bytes":4673536,"current-db-size":"4.7 MB","current-db-size-in-use-bytes":4661248,"current-db-size-in-use":"4.7 MB"}
{"level":"info","ts":"2023-10-28T21:26:38.624288Z","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":-233472,"current-db-size-bytes":4440064,"current-db-size":"4.4 MB","current-db-size-in-use-bytes-diff":-229376,"current-db-size-in-use-bytes":4431872,"current-db-size-in-use":"4.4 MB","took":"138.488952ms"}
{"level":"info","ts":"2023-10-28T21:26:38.624352Z","caller":"v3rpc/maintenance.go:96","msg":"finished defragment"}
time="2023-10-28T21:26:38Z" level=info msg="etcd temporary data store connection OK"
time="2023-10-28T21:26:38Z" level=info msg="Reconciling bootstrap data between datastore and disk"
time="2023-10-28T21:26:38Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T21:26:38Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling ServerCA at '/var/lib/rancher/k3s/server/tls/server-ca.crt'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling ServerCAKey at '/var/lib/rancher/k3s/server/tls/server-ca.key'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling ClientCA at '/var/lib/rancher/k3s/server/tls/client-ca.crt'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling ClientCAKey at '/var/lib/rancher/k3s/server/tls/client-ca.key'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling IPSECKey at '/var/lib/rancher/k3s/server/cred/ipsec.psk'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling PasswdFile at '/var/lib/rancher/k3s/server/cred/passwd'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling RequestHeaderCAKey at '/var/lib/rancher/k3s/server/tls/request-header-ca.key'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling ServiceKey at '/var/lib/rancher/k3s/server/tls/service.key'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling ETCDPeerCA at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.crt'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling ETCDPeerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.key'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling ETCDServerCA at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.crt'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling ETCDServerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.key'"
time="2023-10-28T21:26:38Z" level=debug msg="Reconciling RequestHeaderCA at '/var/lib/rancher/k3s/server/tls/request-header-ca.crt'"
time="2023-10-28T21:26:38Z" level=info msg="Cluster reset: backing up certificates directory to /var/lib/rancher/k3s/server/tls-1698528398"
time="2023-10-28T21:26:38Z" level=warning msg="Updating bootstrap data on disk from datastore"
time="2023-10-28T21:26:38Z" level=info msg="stopping etcd"
{"level":"info","ts":"2023-10-28T21:26:38.642979Z","caller":"embed/etcd.go:376","msg":"closing etcd server","name":"ip-1-1-2-2-648da238","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:26:38.643597Z","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:26:38Z" level=info msg="Retrieving etcd snapshot on-demand-ip-1-1-2-2-1698528266 from S3"
time="2023-10-28T21:26:38Z" level=info msg="Checking if S3 bucket xxxx exists"
{"level":"info","ts":"2023-10-28T21:26:38.66932Z","caller":"embed/etcd.go:579","msg":"stopping serving peer traffic","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T21:26:38.669524Z","caller":"embed/etcd.go:584","msg":"stopped serving peer traffic","address":"127.0.0.1:2400"}
{"level":"info","ts":"2023-10-28T21:26:38.669579Z","caller":"embed/etcd.go:378","msg":"closed etcd server","name":"ip-1-1-2-2-648da238","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:26:38Z" level=info msg="S3 bucket xxxx exists"
time="2023-10-28T21:26:38Z" level=debug msg="Skip setting S3 snapshot cluster ID and token during cluster-reset"
time="2023-10-28T21:26:38Z" level=debug msg="Downloading snapshot from s3://xxxx/xxxx/on-demand-ip-1-1-2-2-1698528266"
time="2023-10-28T21:26:39Z" level=debug msg="Downloading snapshot metadata from s3://xxxx/xxxx/.metadata/on-demand-ip-1-1-2-2-1698528266"
time="2023-10-28T21:26:39Z" level=info msg="S3 download complete for /var/lib/rancher/k3s/server/db/snapshots/on-demand-ip-1-1-2-2-1698528266"
time="2023-10-28T21:26:39Z" level=info msg="Pre-restore etcd database moved to /var/lib/rancher/k3s/server/db/etcd-old-1698528399"
{"level":"info","ts":"2023-10-28T21:26:39.021276Z","caller":"snapshot/v3_snapshot.go:248","msg":"restoring snapshot","path":"/var/lib/rancher/k3s/server/db/snapshots/on-demand-ip-1-1-2-2-1698528266","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:80\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
{"level":"info","ts":"2023-10-28T21:26:39.040451Z","caller":"membership/store.go:141","msg":"Trimming membership information from the backend..."}
{"level":"info","ts":"2023-10-28T21:26:39.05406Z","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-28T21:26:39.066652Z","caller":"snapshot/v3_snapshot.go:269","msg":"restored snapshot","path":"/var/lib/rancher/k3s/server/db/snapshots/on-demand-ip-1-1-2-2-1698528266","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:26:39Z" level=info msg="Starting etcd for new cluster"
{"level":"info","ts":"2023-10-28T21:26:39.067633Z","caller":"embed/etcd.go:127","msg":"configuring peer listeners","listen-peer-urls":["https://127.0.0.1:2380"]}
{"level":"info","ts":"2023-10-28T21:26:39.067667Z","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:26:39.067954Z","caller":"embed/etcd.go:135","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]}
{"level":"info","ts":"2023-10-28T21:26:39.068083Z","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-1-1-2-2-070c50a0","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-28T21:26:39.069335Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","took":"1.045399ms"}
{"level":"info","ts":"2023-10-28T21:26:39.069886Z","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:26:39.069923Z","caller":"etcdserver/server.go:522","msg":"recovered v3 backend from snapshot","backend-size-bytes":4231168,"backend-size":"4.2 MB","backend-size-in-use-bytes":4206592,"backend-size-in-use":"4.2 MB"}
{"level":"info","ts":"2023-10-28T21:26:39.070559Z","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:26:39.070605Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 switched to configuration voters=(471546596056721505)"}
{"level":"info","ts":"2023-10-28T21:26:39.070636Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became follower at term 1"}
{"level":"info","ts":"2023-10-28T21:26:39.070658Z","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:26:39.070729Z","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-28T21:26:39.071597Z","caller":"auth/store.go:1238","msg":"simple token is not cryptographically signed"}
{"level":"info","ts":"2023-10-28T21:26:39.075819Z","caller":"mvcc/kvstore.go:393","msg":"kvstore restored","current-rev":2210}
{"level":"info","ts":"2023-10-28T21:26:39.078293Z","caller":"etcdserver/corrupt.go:95","msg":"starting initial corruption check","local-member-id":"68b452179016861","timeout":"15s"}
{"level":"info","ts":"2023-10-28T21:26:39.079195Z","caller":"etcdserver/corrupt.go:165","msg":"initial corruption checking passed; no corruption","local-member-id":"68b452179016861"}
{"level":"info","ts":"2023-10-28T21:26:39.079239Z","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:26:39.079445Z","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:26:39.079636Z","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:26:39.079738Z","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:26:39.079793Z","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:26:39.080218Z","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:26:39.080438Z","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-28T21:26:39.081848Z","caller":"embed/etcd.go:597","msg":"serving peer traffic","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T21:26:39.081933Z","caller":"embed/etcd.go:569","msg":"cmux::serve","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T21:26:39.100832Z","caller":"embed/etcd.go:855","msg":"serving metrics","address":"http://127.0.0.1:2381"}
time="2023-10-28T21:26:39Z" 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-28T21:26:39Z" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token"
time="2023-10-28T21:26:39Z" 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-28T21:26:39Z" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token"
time="2023-10-28T21:26:39Z" 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-28T21:26:39Z" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml"
time="2023-10-28T21:26:39Z" level=info msg="Run: k3s kubectl"
time="2023-10-28T21:26:39Z" level=warning msg="remove /var/lib/rancher/k3s/agent/etc/k3s-agent-load-balancer.json: no such file or directory"
time="2023-10-28T21:26:39Z" level=info msg="Adding server to load balancer k3s-agent-load-balancer: 127.0.0.1:6443"
time="2023-10-28T21:26:39Z" 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:26:39Z" level=info msg="Cluster-Http-Server 2023/10/28 21:26:39 http: TLS handshake error from 127.0.0.1:47710: remote error: tls: bad certificate"
time="2023-10-28T21:26:39Z" level=info msg="Cluster-Http-Server 2023/10/28 21:26:39 http: TLS handshake error from 127.0.0.1:47748: remote error: tls: bad certificate"
{"level":"info","ts":"2023-10-28T21:26:39.570864Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 is starting a new election at term 1"}
{"level":"info","ts":"2023-10-28T21:26:39.570934Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became pre-candidate at term 1"}
{"level":"info","ts":"2023-10-28T21:26:39.571252Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 received MsgPreVoteResp from 68b452179016861 at term 1"}
{"level":"info","ts":"2023-10-28T21:26:39.571307Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became candidate at term 2"}
{"level":"info","ts":"2023-10-28T21:26:39.571424Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 received MsgVoteResp from 68b452179016861 at term 2"}
{"level":"info","ts":"2023-10-28T21:26:39.571588Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"68b452179016861 became leader at term 2"}
{"level":"info","ts":"2023-10-28T21:26:39.571638Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 68b452179016861 elected leader 68b452179016861 at term 2"}
{"level":"info","ts":"2023-10-28T21:26:39.576041Z","caller":"etcdserver/server.go:2064","msg":"published local member to cluster through raft","local-member-id":"68b452179016861","local-member-attributes":"{Name:ip-1-1-2-2-070c50a0 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:26:39.576087Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T21:26:39.576381Z","caller":"etcdserver/server.go:2573","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"}
{"level":"info","ts":"2023-10-28T21:26:39.577507Z","caller":"embed/serve.go:103","msg":"ready to serve client requests"}
{"level":"info","ts":"2023-10-28T21:26:39.579768Z","caller":"embed/serve.go:250","msg":"serving client traffic securely","traffic":"grpc","address":"127.0.0.1:2379"}
{"level":"info","ts":"2023-10-28T21:26:39.581158Z","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:26:39.581364Z","caller":"etcdserver/server.go:2597","msg":"cluster version is updated","cluster-version":"3.5"}
{"level":"info","ts":"2023-10-28T21:26:39.5822Z","caller":"embed/serve.go:250","msg":"serving client traffic securely","traffic":"http","address":"127.0.0.1:2382"}
time="2023-10-28T21:26:39Z" level=info msg="Defragmenting etcd database"
{"level":"info","ts":"2023-10-28T21:26:39.620916Z","caller":"v3rpc/maintenance.go:90","msg":"starting defragment"}
{"level":"info","ts":"2023-10-28T21:26:39.624421Z","caller":"backend/backend.go:497","msg":"defragmenting","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","current-db-size-bytes":4231168,"current-db-size":"4.2 MB","current-db-size-in-use-bytes":4210688,"current-db-size-in-use":"4.2 MB"}
{"level":"info","ts":"2023-10-28T21:26:39.690495Z","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":-180224,"current-db-size-bytes":4050944,"current-db-size":"4.1 MB","current-db-size-in-use-bytes-diff":-167936,"current-db-size-in-use-bytes":4042752,"current-db-size-in-use":"4.0 MB","took":"69.487853ms"}
{"level":"info","ts":"2023-10-28T21:26:39.690601Z","caller":"v3rpc/maintenance.go:96","msg":"finished defragment"}
time="2023-10-28T21:26:39Z" level=info msg="etcd data store connection OK"
time="2023-10-28T21:26:39Z" level=info msg="Saving cluster bootstrap data to datastore"
time="2023-10-28T21:26:39Z" level=info msg="Waiting for API server to become available"
time="2023-10-28T21:26:39Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T21:26:39Z" level=info msg="ETCD server is now running"
time="2023-10-28T21:26:39Z" level=info msg="k3s is up and running"
time="2023-10-28T21:26:39Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T21:26:39Z" level=warning msg="Bootstrap key already exists"
time="2023-10-28T21:26:40Z" level=info msg="Password verified locally for node ip-1-1-2-2"
time="2023-10-28T21:26:40Z" level=info msg="certificate CN=ip-1-1-2-2 signed by CN=k3s-server-ca@1698527997: notBefore=2023-10-28 21:19:57 +0000 UTC notAfter=2024-10-27 21:26:40 +0000 UTC"
time="2023-10-28T21:26:41Z" level=info msg="certificate CN=system:node:ip-1-1-2-2,O=system:nodes signed by CN=k3s-client-ca@1698527997: notBefore=2023-10-28 21:19:57 +0000 UTC notAfter=2024-10-27 21:26:41 +0000 UTC"
time="2023-10-28T21:26:42Z" level=debug msg="Tunnel server handing HTTP/1.1 GET request for /v1-k3s/connect from 18.221.175.196:49808"
time="2023-10-28T21:26:42Z" level=info msg="Handling backend connection request [ip-3-3-4-4]"
time="2023-10-28T21:26:46Z" level=info msg="Defragmenting etcd database"
{"level":"info","ts":"2023-10-28T21:26:46.783236Z","caller":"v3rpc/maintenance.go:90","msg":"starting defragment"}
{"level":"info","ts":"2023-10-28T21:26:46.793481Z","caller":"backend/backend.go:497","msg":"defragmenting","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","current-db-size-bytes":4050944,"current-db-size":"4.1 MB","current-db-size-in-use-bytes":4042752,"current-db-size-in-use":"4.0 MB"}
{"level":"info","ts":"2023-10-28T21:26:46.873664Z","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":4050944,"current-db-size":"4.1 MB","current-db-size-in-use-bytes-diff":0,"current-db-size-in-use-bytes":4042752,"current-db-size-in-use":"4.0 MB","took":"90.331294ms"}
{"level":"info","ts":"2023-10-28T21:26:46.87377Z","caller":"v3rpc/maintenance.go:96","msg":"finished defragment"}
time="2023-10-28T21:26:46Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T21:26:46Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T21:26:46Z" level=info msg="Reconciling bootstrap data between datastore and disk"
time="2023-10-28T21:26:46Z" level=debug msg="Comparing /bootstrap/2bb80d537b1d to /bootstrap/2bb80d537b1d"
time="2023-10-28T21:26:46Z" level=debug msg="checking bootstrap key /bootstrap/2bb80d537b1d against /bootstrap/2bb80d537b1d"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling ETCDPeerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.key'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling ETCDServerCAKey at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.key'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling IPSECKey at '/var/lib/rancher/k3s/server/cred/ipsec.psk'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling RequestHeaderCA at '/var/lib/rancher/k3s/server/tls/request-header-ca.crt'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling RequestHeaderCAKey at '/var/lib/rancher/k3s/server/tls/request-header-ca.key'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling ServerCA at '/var/lib/rancher/k3s/server/tls/server-ca.crt'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling ServiceKey at '/var/lib/rancher/k3s/server/tls/service.key'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling ClientCA at '/var/lib/rancher/k3s/server/tls/client-ca.crt'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling ClientCAKey at '/var/lib/rancher/k3s/server/tls/client-ca.key'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling ETCDPeerCA at '/var/lib/rancher/k3s/server/tls/etcd/peer-ca.crt'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling ETCDServerCA at '/var/lib/rancher/k3s/server/tls/etcd/server-ca.crt'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling PasswdFile at '/var/lib/rancher/k3s/server/cred/passwd'"
time="2023-10-28T21:26:46Z" level=debug msg="Reconciling ServerCAKey at '/var/lib/rancher/k3s/server/tls/server-ca.key'"
time="2023-10-28T21:26:46Z" level=info msg="Cluster reset: backing up certificates directory to /var/lib/rancher/k3s/server/tls-1698528406"
time="2023-10-28T21:26:46Z" level=warning msg="Updating bootstrap data on disk from datastore"
time="2023-10-28T21:26:46Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1698527997: notBefore=2023-10-28 21:19:57 +0000 UTC notAfter=2024-10-27 21:26:46 +0000 UTC"
time="2023-10-28T21:26:46Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1698527997: notBefore=2023-10-28 21:19:57 +0000 UTC notAfter=2024-10-27 21:26:46 +0000 UTC"
time="2023-10-28T21:26:46Z" level=info msg="stopping etcd"
{"level":"info","ts":"2023-10-28T21:26:46.920109Z","caller":"embed/etcd.go:376","msg":"closing etcd server","name":"ip-1-1-2-2-070c50a0","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-28T21:26:46.921361Z","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:26:46.931023Z","caller":"embed/etcd.go:579","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T21:26:46.931282Z","caller":"embed/etcd.go:584","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"}
{"level":"info","ts":"2023-10-28T21:26:46.931332Z","caller":"embed/etcd.go:378","msg":"closed etcd server","name":"ip-1-1-2-2-070c50a0","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-28T21:26:51Z" 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 On SERVER1: 18.116.26.226
NAME STATUS ROLES AGE VERSION
ip-1-1-1-1 Ready <none> 11m v1.27.7-rc2+k3s1
ip-2-2-2-2 Ready control-plane,etcd,master 13m v1.27.7-rc2+k3s1
ip-3-3-3-3 Ready control-plane,etcd,master 12m v1.27.7-rc2+k3s1
ip-4-4-4-4 Ready control-plane,etcd,master 14m v1.27.7-rc2+k3s1
$ sudo /usr/local/bin/kubectl --kubeconfig /etc/rancher/k3s/k3s.yaml get pods -A On SERVER1: 18.116.26.226
NAMESPACE NAME READY STATUS RESTARTS AGE
auto-clusterip test-clusterip-64d4dcfdd4-pp59x 1/1 Running 1 (4m59s ago) 10m
auto-clusterip test-clusterip-64d4dcfdd4-sl88q 1/1 Running 0 10m
auto-daemonset test-daemonset-4m5l6 1/1 Running 1 (3m33s ago) 10m
auto-daemonset test-daemonset-h8m5v 1/1 Running 0 10m
auto-daemonset test-daemonset-hshtt 1/1 Running 1 (4m59s ago) 10m
auto-daemonset test-daemonset-xq6gw 1/1 Running 0 10m
auto-dns dnsutils 1/1 Running 1 (3m33s ago) 10m
auto-ingress test-ingress-9h485 1/1 Running 0 10m
auto-ingress test-ingress-zdn5l 1/1 Running 1 (4m59s ago) 10m
auto-nodeport test-nodeport-5b846cdb6d-2bvwl 1/1 Running 1 (3m33s ago) 10m
auto-nodeport test-nodeport-5b846cdb6d-wsch5 1/1 Running 0 10m
clusterip clusterip-pod-demo 1/1 Running 1 (4m59s ago) 10m
clusterip clusterip-pod-demo-2 1/1 Running 1 (3m33s ago) 10m
clusterip clusterip-pod-demo-3 1/1 Running 0 10m
default clusterip-pod-demo 1/1 Running 0 10m
default clusterip-pod-demo-2 1/1 Running 1 (3m33s ago) 10m
default clusterip-pod-demo-3 1/1 Running 1 (4m59s ago) 10m
kube-system coredns-77ccd57875-mhgjd 1/1 Running 0 13m
kube-system helm-install-traefik-crd-xkqvm 0/1 Completed 0 13m
kube-system helm-install-traefik-l47ct 0/1 Completed 1 13m
kube-system local-path-provisioner-957fdf8bc-zkgpf 1/1 Running 0 13m
kube-system metrics-server-648b5df564-kwfhp 1/1 Running 0 13m
kube-system svclb-traefik-3df806f2-9qw24 2/2 Running 0 13m
kube-system svclb-traefik-3df806f2-j49st 2/2 Running 0 11m
kube-system svclb-traefik-3df806f2-q6bmk 2/2 Running 2 (4m59s ago) 13m
kube-system svclb-traefik-3df806f2-t4wdn 2/2 Running 2 (3m33s ago) 12m
kube-system traefik-7fbbb44c44-5lj85 1/1 Running 0 13m
Backport fix for Cluster Restore for s3 snapshot fails
8727