Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

[Release-1.26] - Cluster Restore for s3 snapshot fails #8731

Closed
brandond opened this issue Oct 27, 2023 · 1 comment
Closed

[Release-1.26] - Cluster Restore for s3 snapshot fails #8731

brandond opened this issue Oct 27, 2023 · 1 comment
Assignees
@brandond @aganesh-suse
Milestone
v1.26.10+k3s1

Comments

@brandond
Copy link
Contributor

Backport fix for Cluster Restore for s3 snapshot fails
@brandond brandond self-assigned this Oct 27, 2023
@brandond brandond mentioned this issue Oct 27, 2023
Merged
@brandond brandond added this to the v1.26.10+k3s1 milestone Oct 27, 2023
@aganesh-suse
Copy link

aganesh-suse commented Oct 30, 2023 •
edited

Validated on release-1.26 branch with version v1.26.10-rc2+k3s1

Environment Details

Infrastructure

  • Cloud
  • Hosted

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
  1. Install k3s
curl -sfL https://get.k3s.io | sudo INSTALL_K3S_VERSION='v1.26.10-rc2+k3s1' sh -s - server
  1. Verify Cluster Status:
kubectl get nodes -o wide
kubectl get pods -A
  1. Apply some workloads
  2. 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"
  1. Kill servers 2 and 3:
sudo k3s-killall.sh
  1. Stop k3s server on server1
sudo systemctl stop k3s
  1. Run cluster reset from s3 snapshot saved:
sudo k3s server --cluster-reset --etcd-s3   --cluster-reset-restore-path=on-demand-ip-1-1-1-1-1698343463   --etcd-s3-bucket=xxxx --etcd-s3-folder=xxxx --etcd-s3-region=xxxx   --etcd-s3-access-key=xxxx --etcd-s3-secret-key="xxxx"   --token=xxxx
  1. Start k3s services on servers 1, 2 and 3:
sudo systemctl start k3s
  1. Make sure all pods/services are running as expected in the k3s cluster - including the workloads stored in the snapshot
kubectl get nodes -o wide
kubectl get pods -A

Validation Results:

  • k3s version used for validation:
 $ k3s -v 
k3s version v1.26.10-rc2+k3s1 (a6687b59)
go version go1.20.10

Cluster reset with s3 snapshot result:

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

K3S Cluster Status:

 $ sudo /usr/local/bin/kubectl --kubeconfig /etc/rancher/k3s/k3s.yaml get nodes 
NAME                STATUS   ROLES                       AGE   VERSION
ip-1-1-1-1          Ready    <none>                      23m   v1.26.10-rc2+k3s1
ip-2-2-2-2          Ready    control-plane,etcd,master   25m   v1.26.10-rc2+k3s1
ip-3-3-3-3          Ready    control-plane,etcd,master   24m   v1.26.10-rc2+k3s1
ip-4-4-4-4          Ready    control-plane,etcd,master   26m   v1.26.10-rc2+k3s1
======= Execute DONE ========
======= Execute START ========
 $ sudo /usr/local/bin/kubectl --kubeconfig /etc/rancher/k3s/k3s.yaml get pods -A 
NAMESPACE        NAME                                      READY   STATUS      RESTARTS      AGE
auto-clusterip   test-clusterip-5f695f5786-ldwtt           1/1     Running     0             22m
auto-clusterip   test-clusterip-5f695f5786-vzzm6           1/1     Running     1 (17m ago)   22m
auto-daemonset   test-daemonset-6gkh5                      1/1     Running     0             22m
auto-daemonset   test-daemonset-9t5dt                      1/1     Running     1 (16m ago)   22m
auto-daemonset   test-daemonset-bzvxf                      1/1     Running     0             22m
auto-daemonset   test-daemonset-nskxh                      1/1     Running     1 (17m ago)   22m
auto-dns         dnsutils                                  1/1     Running     1 (16m ago)   22m
auto-ingress     test-ingress-6q9c4                        1/1     Running     1 (16m ago)   22m
auto-ingress     test-ingress-x4vcm                        1/1     Running     1 (17m ago)   22m
auto-nodeport    test-nodeport-6db7c7d54-5fltx             1/1     Running     1 (16m ago)   22m
auto-nodeport    test-nodeport-6db7c7d54-ssk9f             1/1     Running     0             22m
clusterip        clusterip-pod-demo                        1/1     Running     0             22m
clusterip        clusterip-pod-demo-2                      1/1     Running     1 (17m ago)   22m
clusterip        clusterip-pod-demo-3                      1/1     Running     1 (16m ago)   22m
default          clusterip-pod-demo                        1/1     Running     1 (17m ago)   22m
default          clusterip-pod-demo-2                      1/1     Running     0             22m
default          clusterip-pod-demo-3                      1/1     Running     1 (16m ago)   22m
kube-system      coredns-59b4f5bbd5-dhz5m                  1/1     Running     0             26m
kube-system      helm-install-traefik-crd-pncv9            0/1     Completed   0             26m
kube-system      helm-install-traefik-kdfgt                0/1     Completed   1             26m
kube-system      local-path-provisioner-76d776f6f9-c2szh   1/1     Running     0             26m
kube-system      metrics-server-68cf49699b-2mbdw           1/1     Running     0             26m
kube-system      svclb-traefik-81dfbde1-lcvh7              2/2     Running     0             25m
kube-system      svclb-traefik-81dfbde1-qs6px              2/2     Running     0             24m
kube-system      svclb-traefik-81dfbde1-qvzdf              2/2     Running     2 (17m ago)   25m
kube-system      svclb-traefik-81dfbde1-tb7l9              2/2     Running     2 (16m ago)   24m
kube-system      traefik-f75d47c4b-zfznz                   1/1     Running     0             25m

@aganesh-suse aganesh-suse self-assigned this Oct 30, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@brandond brandond

@aganesh-suse aganesh-suse

Labels
None yet
Projects
K3s Development
Archived in project
Milestone
v1.26.10+k3s1
Development

No branches or pull requests
2 participants
@brandond @aganesh-suse