Etcd extentensivly logging error "bucket already exists"

[serathius]

Bug report criteria

• This bug report is not security related, security issues should be disclosed privately via security@etcd.io.
• This is not a support request or question, support requests or questions should be raised in the etcd discussion forums.
• You have read the etcd bug reporting guidelines.
• Existing open issues along with etcd frequently asked questions have been checked and this is not a duplicate.

What happened?

Looked at etcd logs in CI and found a lot of Creating bucket "XXX" failed: bucket already exists logs. This happens 1 time when starting from empty data dir and 11 times on etcd restart.

This happens on main branch, however with recent changes and backports to backend transactions, it might also appear in release-3.4 and release-3.5. Needs to be confirmed.

What did you expect to happen?

I would expect that etcd doesn't write error logs during normal correct function, especially in such big number.

How can we reproduce it (as minimally and precisely as possible)?

make && ./bin/etcd

Anything else we need to know?

No response

Etcd version (please run commands below)

main branch

Etcd configuration (command line flags or environment variables)

n/a

Etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

N/A

Relevant log output

{"level":"warn","ts":"2024-01-15T16:35:55.284938+0100","caller":"embed/config.go:893","msg":"Running http and grpc server on single port. This is not recommended for production."}
{"level":"warn","ts":"2024-01-15T16:35:55.285045+0100","caller":"embed/config.go:995","msg":"it isn't recommended to use default name, please set a value for --name. Note that etcd might run into issue when multiple members have the same default name","name":"default"}
{"level":"info","ts":"2024-01-15T16:35:55.28506+0100","caller":"etcdmain/etcd.go:63","msg":"Running: ","args":["./bin/etcd"]}
{"level":"warn","ts":"2024-01-15T16:35:55.285085+0100","caller":"etcdmain/etcd.go:95","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"}
{"level":"info","ts":"2024-01-15T16:35:55.285104+0100","caller":"etcdmain/etcd.go:123","msg":"Initialize and start etcd server","data-dir":"default.etcd","dir-type":"empty"}
{"level":"warn","ts":"2024-01-15T16:35:55.285119+0100","caller":"embed/config.go:893","msg":"Running http and grpc server on single port. This is not recommended for production."}
{"level":"warn","ts":"2024-01-15T16:35:55.285129+0100","caller":"embed/config.go:995","msg":"it isn't recommended to use default name, please set a value for --name. Note that etcd might run into issue when multiple members have the same default name","name":"default"}
{"level":"info","ts":"2024-01-15T16:35:55.285142+0100","caller":"embed/etcd.go:125","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]}
{"level":"info","ts":"2024-01-15T16:35:55.285627+0100","caller":"embed/etcd.go:133","msg":"configuring client listeners","listen-client-urls":["http://localhost:2379"]}
{"level":"info","ts":"2024-01-15T16:35:55.285823+0100","caller":"embed/etcd.go:311","msg":"starting an etcd server","etcd-version":"3.6.0-alpha.0","git-sha":"fbcfd4e94","go-version":"go1.21.1","go-os":"linux","go-arch":"amd64","max-cpu-set":24,"max-cpu-available":24,"member-initialized":false,"name":"default","data-dir":"default.etcd","wal-dir":"","wal-dir-dedicated":"","member-dir":"default.etcd/member","force-new-cluster":false,"heartbeat-interval":"100ms","election-timeout":"1s","initial-election-tick-advance":true,"snapshot-count":10000,"max-wals":5,"max-snapshots":5,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["http://localhost:2380"],"listen-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"],"listen-client-urls":["http://localhost:2379"],"listen-metrics-urls":[],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"default=http://localhost:2380","initial-cluster-state":"new","initial-cluster-token":"etcd-cluster","quota-backend-bytes":2147483648,"max-request-bytes":1572864,"max-concurrent-streams":4294967295,"pre-vote":true,"initial-corrupt-check":false,"corrupt-check-time-interval":"0s","compact-check-time-enabled":false,"compact-check-time-interval":"1m0s","auto-compaction-mode":"periodic","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":"","discovery-token":"","discovery-endpoints":"","discovery-dial-timeout":"2s","discovery-request-timeout":"5s","discovery-keepalive-time":"2s","discovery-keepalive-timeout":"6s","discovery-insecure-transport":true,"discovery-insecure-skip-tls-verify":false,"discovery-cert":"","discovery-key":"","discovery-cacert":"","discovery-user":"","downgrade-check-interval":"5s","max-learners":1}
{"level":"info","ts":"2024-01-15T16:35:55.286595+0100","logger":"bbolt","caller":"backend/backend.go:185","msg":"Opening db file (default.etcd/member/snap/db) with mode 2d72772d2d2d2d2d2d2d and with options: {Timeout: 0s, NoGrowSync: false, NoFreelistSync: true, PreLoadFreelist: false, FreelistType: hashmap, ReadOnly: false, MmapFlags: 8000, InitialMmapSize: 10737418240, PageSize: 0, NoSync: false, OpenFile: 0x0, Mlock: false, Logger: 0xc00038c360}"}
{"level":"info","ts":"2024-01-15T16:35:55.293536+0100","logger":"bbolt","caller":"bbolt@v1.4.0-alpha.0/db.go:319","msg":"Opening bbolt db (default.etcd/member/snap/db) successfully"}
{"level":"info","ts":"2024-01-15T16:35:55.293583+0100","caller":"storage/backend.go:80","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"7.060964ms"}
{"level":"info","ts":"2024-01-15T16:35:55.293618+0100","caller":"etcdserver/bootstrap.go:93","msg":"bootstrapping cluster"}
{"level":"info","ts":"2024-01-15T16:35:55.293655+0100","caller":"etcdserver/bootstrap.go:100","msg":"bootstrapping storage"}
{"level":"info","ts":"2024-01-15T16:35:55.308053+0100","caller":"etcdserver/bootstrap.go:108","msg":"bootstrapping raft"}
{"level":"info","ts":"2024-01-15T16:35:55.308162+0100","caller":"etcdserver/bootstrap.go:493","msg":"starting local member","local-member-id":"8e9e05c52164694d","cluster-id":"cdf818194e3a8c32"}
{"level":"info","ts":"2024-01-15T16:35:55.308182+0100","caller":"etcdserver/server.go:304","msg":"bootstrap successfully"}
{"level":"info","ts":"2024-01-15T16:35:55.308257+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:1920","msg":"8e9e05c52164694d switched to configuration voters=()"}
{"level":"info","ts":"2024-01-15T16:35:55.308309+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:870","msg":"8e9e05c52164694d became follower at term 0"}
{"level":"info","ts":"2024-01-15T16:35:55.308323+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:483","msg":"newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"}
{"level":"info","ts":"2024-01-15T16:35:55.308346+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:870","msg":"8e9e05c52164694d became follower at term 1"}
{"level":"info","ts":"2024-01-15T16:35:55.308384+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:1920","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"}
{"level":"warn","ts":"2024-01-15T16:35:55.323106+0100","caller":"auth/store.go:1134","msg":"simple token is not cryptographically signed"}
{"level":"error","ts":"2024-01-15T16:35:55.323151+0100","logger":"bbolt","caller":"bbolt@v1.4.0-alpha.0/bucket.go:178","msg":"Creating bucket \"meta\" failed: bucket already exists","stacktrace":"go.etcd.io/bbolt.(*Bucket).CreateBucket\n\tgo.etcd.io/bbolt@v1.4.0-alpha.0/bucket.go:178\ngo.etcd.io/bbolt.(*Tx).CreateBucket\n\tgo.etcd.io/bbolt@v1.4.0-alpha.0/tx.go:119\ngo.etcd.io/etcd/server/v3/storage/backend.(*batchTx).UnsafeCreateBucket\n\tgo.etcd.io/etcd/server/v3/storage/backend/batch_tx.go:115\ngo.etcd.io/etcd/server/v3/storage/schema.UnsafeCreateMetaBucket\n\tgo.etcd.io/etcd/server/v3/storage/schema/cindex.go:27\ngo.etcd.io/etcd/server/v3/storage/mvcc.NewStore\n\tgo.etcd.io/etcd/server/v3/storage/mvcc/kvstore.go:118\ngo.etcd.io/etcd/server/v3/storage/mvcc.newWatchableStore\n\tgo.etcd.io/etcd/server/v3/storage/mvcc/watchable_store.go:84\ngo.etcd.io/etcd/server/v3/storage/mvcc.New\n\tgo.etcd.io/etcd/server/v3/storage/mvcc/watchable_store.go:76\ngo.etcd.io/etcd/server/v3/etcdserver.NewServer\n\tgo.etcd.io/etcd/server/v3/etcdserver/server.go:369\ngo.etcd.io/etcd/server/v3/embed.StartEtcd\n\tgo.etcd.io/etcd/server/v3/embed/etcd.go:250\ngo.etcd.io/etcd/server/v3/etcdmain.startEtcd\n\tgo.etcd.io/etcd/server/v3/etcdmain/etcd.go:205\ngo.etcd.io/etcd/server/v3/etcdmain.startEtcdOrProxyV2\n\tgo.etcd.io/etcd/server/v3/etcdmain/etcd.go:128\ngo.etcd.io/etcd/server/v3/etcdmain.Main\n\tgo.etcd.io/etcd/server/v3/etcdmain/main.go:40\nmain.main\n\tgo.etcd.io/etcd/server/v3/main.go:31\nruntime.main\n\truntime/proc.go:267"}
{"level":"info","ts":"2024-01-15T16:35:55.327873+0100","caller":"mvcc/kvstore.go:393","msg":"kvstore restored","current-rev":1}
{"level":"info","ts":"2024-01-15T16:35:55.335719+0100","caller":"storage/quota.go:93","msg":"enabled backend quota with default value","quota-name":"v3-applier","quota-size-bytes":2147483648,"quota-size":"2.1 GB"}
{"level":"info","ts":"2024-01-15T16:35:55.335774+0100","caller":"etcdserver/server.go:583","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.6.0-alpha.0","cluster-version":"to_be_decided"}
{"level":"info","ts":"2024-01-15T16:35:55.335866+0100","caller":"etcdserver/server.go:468","msg":"started as single-node; fast-forwarding election ticks","local-member-id":"8e9e05c52164694d","forward-ticks":9,"forward-duration":"900ms","election-ticks":10,"election-timeout":"1s"}
{"level":"info","ts":"2024-01-15T16:35:55.33591+0100","caller":"embed/etcd.go:280","msg":"now serving peer/client/metrics","local-member-id":"8e9e05c52164694d","initial-advertise-peer-urls":["http://localhost:2380"],"listen-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"],"listen-client-urls":["http://localhost:2379"],"listen-metrics-urls":[]}
{"level":"info","ts":"2024-01-15T16:35:55.335926+0100","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"}
{"level":"info","ts":"2024-01-15T16:35:55.335981+0100","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"}
{"level":"info","ts":"2024-01-15T16:35:55.33596+0100","caller":"embed/etcd.go:604","msg":"serving peer traffic","address":"127.0.0.1:2380"}
{"level":"info","ts":"2024-01-15T16:35:55.336028+0100","caller":"embed/etcd.go:576","msg":"cmux::serve","address":"127.0.0.1:2380"}
{"level":"info","ts":"2024-01-15T16:35:55.336004+0100","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"}
{"level":"info","ts":"2024-01-15T16:35:55.336172+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:1920","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"}
{"level":"info","ts":"2024-01-15T16:35:55.336275+0100","caller":"membership/cluster.go:411","msg":"added member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","added-peer-id":"8e9e05c52164694d","added-peer-peer-urls":["http://localhost:2380"],"added-peer-is-learner":false}
{"level":"info","ts":"2024-01-15T16:35:56.009268+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:956","msg":"8e9e05c52164694d is starting a new election at term 1"}
{"level":"info","ts":"2024-01-15T16:35:56.009323+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:899","msg":"8e9e05c52164694d became pre-candidate at term 1"}
{"level":"info","ts":"2024-01-15T16:35:56.009386+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:1043","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 1"}
{"level":"info","ts":"2024-01-15T16:35:56.009403+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:1649","msg":"8e9e05c52164694d has received 1 MsgPreVoteResp votes and 0 vote rejections"}
{"level":"info","ts":"2024-01-15T16:35:56.009427+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:883","msg":"8e9e05c52164694d became candidate at term 2"}
{"level":"info","ts":"2024-01-15T16:35:56.011274+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:1043","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 2"}
{"level":"info","ts":"2024-01-15T16:35:56.011301+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:1649","msg":"8e9e05c52164694d has received 1 MsgVoteResp votes and 0 vote rejections"}
{"level":"info","ts":"2024-01-15T16:35:56.011323+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/raft.go:938","msg":"8e9e05c52164694d became leader at term 2"}
{"level":"info","ts":"2024-01-15T16:35:56.011336+0100","logger":"raft","caller":"v3@v3.6.0-alpha.0/node.go:370","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2"}
{"level":"info","ts":"2024-01-15T16:35:56.013381+0100","caller":"etcdserver/server.go:1756","msg":"published local member to cluster through raft","local-member-id":"8e9e05c52164694d","local-member-attributes":"{Name:default ClientURLs:[http://localhost:2379]}","cluster-id":"cdf818194e3a8c32","publish-timeout":"7s"}
{"level":"info","ts":"2024-01-15T16:35:56.013434+0100","caller":"embed/serve.go:104","msg":"ready to serve client requests"}
{"level":"info","ts":"2024-01-15T16:35:56.013468+0100","caller":"etcdserver/server.go:2299","msg":"setting up initial cluster version using v3 API","cluster-version":"3.6"}
{"level":"info","ts":"2024-01-15T16:35:56.013596+0100","caller":"etcdmain/main.go:44","msg":"notifying init daemon"}
{"level":"info","ts":"2024-01-15T16:35:56.01367+0100","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"}
{"level":"info","ts":"2024-01-15T16:35:56.015442+0100","caller":"membership/cluster.go:594","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.6"}
{"level":"info","ts":"2024-01-15T16:35:56.015534+0100","caller":"api/capability.go:76","msg":"enabled capabilities for version","cluster-version":"3.6"}
{"level":"info","ts":"2024-01-15T16:35:56.015574+0100","caller":"etcdserver/server.go:2319","msg":"cluster version is updated","cluster-version":"3.6"}
{"level":"info","ts":"2024-01-15T16:35:56.015588+0100","caller":"v3rpc/health.go:62","msg":"grpc service status changed","service":"","status":"SERVING"}
{"level":"info","ts":"2024-01-15T16:35:56.01568+0100","caller":"version/monitor.go:116","msg":"cluster version differs from storage version.","cluster-version":"3.6.0","storage-version":"3.5.0"}
{"level":"info","ts":"2024-01-15T16:35:56.015729+0100","caller":"schema/migration.go:65","msg":"updated storage version","new-storage-version":"3.6.0"}
{"level":"info","ts":"2024-01-15T16:35:56.017498+0100","caller":"embed/serve.go:188","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"127.0.0.1:2379"}

[serathius]

cc @ahrtr

Maybe effect of enabling bbolt logging.

[ahrtr]

Please read #17249

[ahrtr]

Followup #17249 (comment)

[serathius]

Created an dedicated followup issue #17329